3.13.5 kernel hangs some processes with btrfs

3.13.5 kernel hangs some processes with btrfs

[Marc MERLIN]

Does someone know how I can debug further why this is hanging?

It seems that accessing a certain directory on one of my btrfs filesystems
causes this.

The rest of my system seems ok, as long as I'm not touching this filesystem.

Is this a bug, or a performance problem?

[ 1930.287192] INFO: task mc:4759 blocked for more than 120 seconds.
[ 1930.323551]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 1930.360857] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1930.408072] mc              D c18d2600     0  4759   4568 0x00000084
[ 1930.445960]  f10f9e88 00000082 c18d2600 c18d2600 00000000 00000000 f3e38c80 00000000
[ 1930.492442]  ef34c490 00000e27 00000000 f10f9e58 c11d3ce9 00001000 00000002 00000000
[ 1930.538992]  00000e25 f10f9e64 c1062374 00000246 f10f9e74 00000246 f10f9e74 c150348b
[ 1930.585546] Call Trace:
[ 1930.600231]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 1930.635615]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 1930.667889]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 1930.704425]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 1930.737751]  [<c1501477>] schedule+0x63/0x65
[ 1930.763255]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 1930.798146]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 1930.826278]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 1930.857529]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 1930.890353]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 1930.920576]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 1930.950781]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 1930.982039]  [<c11140f0>] update_time+0x1e/0x95
[ 1931.009124]  [<c111474d>] touch_atime+0xd1/0x105
[ 1931.036727]  [<c110f201>] iterate_dir+0x87/0x9f
[ 1931.063819]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 1931.092482]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 1931.127855]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 2051.257792] INFO: task mc:4759 blocked for more than 120 seconds.
[ 2051.294060]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 2051.331042] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2051.377904] mc              D c18d2600     0  4759   4568 0x00000084
[ 2051.415943]  f10f9e88 00000082 c18d2600 c18d2600 00000000 00000000 f3e38c80 00000000
[ 2051.465288]  ef34c490 00000e27 00000000 f10f9e58 c11d3ce9 00001000 00000002 00000000
[ 2051.514381]  00000e25 f10f9e64 c1062374 00000246 f10f9e74 00000246 f10f9e74 c150348b
[ 2051.565902] Call Trace:
[ 2051.582441]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 2051.619402]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 2051.653297]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 2051.691230]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 2051.726027]  [<c1501477>] schedule+0x63/0x65
[ 2051.753324]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 2051.790796]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 2051.821899]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 2051.855772]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 2051.890151]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 2051.921943]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 2051.954211]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 2051.986914]  [<c11140f0>] update_time+0x1e/0x95
[ 2052.015485]  [<c111474d>] touch_atime+0xd1/0x105
[ 2052.044702]  [<c110f201>] iterate_dir+0x87/0x9f
[ 2052.073201]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 2052.103355]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 2052.130848]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 2096.805058] perf samples too long (2503 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
[ 2096.861168] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 56.110 msecs
[ 2172.260339] INFO: task mc:4759 blocked for more than 120 seconds.
[ 2172.298384]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 2172.338045] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2172.387803] mc              D c18d2600     0  4759   4568 0x00000084
[ 2172.427411]  f10f9e88 00000082 c18d2600 c18d2600 00000000 00000000 f3e38c80 00000000
[ 2172.475461]  ef34c490 00000e27 00000000 f10f9e58 c11d3ce9 00001000 00000002 00000000
[ 2172.523521]  00000e25 f10f9e64 c1062374 00000246 f10f9e74 00000246 f10f9e74 c150348b
[ 2172.571674] Call Trace:
[ 2172.587871]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 2172.624823]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 2172.659881]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 2172.698558]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 2172.733853]  [<c1501477>] schedule+0x63/0x65
[ 2172.762269]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 2172.799382]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 2172.830296]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 2172.868749]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 2172.908785]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 2172.944813]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 2172.977512]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 2173.010264]  [<c11140f0>] update_time+0x1e/0x95
[ 2173.038796]  [<c111474d>] touch_atime+0xd1/0x105
[ 2173.073517]  [<c110f201>] iterate_dir+0x87/0x9f
[ 2173.102140]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 2173.133333]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 2173.160751]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 2293.290687] INFO: task mc:4759 blocked for more than 120 seconds.
[ 2293.331803]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 2293.373134] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2293.422548] mc              D c18d2600     0  4759   4568 0x00000084
[ 2293.461998]  f10f9e88 00000082 c18d2600 c18d2600 00000000 00000000 f3e38c80 00000000
[ 2293.510991]  ef34c490 00000e27 00000000 f10f9e58 c11d3ce9 00001000 00000002 00000000
[ 2293.559835]  00000e25 f10f9e64 c1062374 00000246 f10f9e74 00000246 f10f9e74 c150348b
[ 2293.607832] Call Trace:
[ 2293.623798]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 2293.661353]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 2293.696040]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 2293.734968]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 2293.770187]  [<c1501477>] schedule+0x63/0x65
[ 2293.797124]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 2293.833396]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 2293.864027]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 2293.896638]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 2293.931754]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 2293.963336]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 2293.994908]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 2294.027580]  [<c11140f0>] update_time+0x1e/0x95
[ 2294.056016]  [<c111474d>] touch_atime+0xd1/0x105
[ 2294.085036]  [<c110f201>] iterate_dir+0x87/0x9f
[ 2294.114382]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 2294.144591]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 2294.172042]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 2414.300956] INFO: task mc:4759 blocked for more than 120 seconds.
[ 2414.340086]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 2414.384979] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2414.453036] mc              D c18d2600     0  4759   4568 0x00000084
[ 2414.493492]  f10f9e88 00000082 c18d2600 c18d2600 00000000 00000000 f3e38c80 00000000
[ 2414.543276]  ef34c490 00000e27 00000000 f10f9e58 c11d3ce9 00001000 00000002 00000000
[ 2414.591394]  00000e25 f10f9e64 c1062374 00000246 f10f9e74 00000246 f10f9e74 c150348b
[ 2414.640205] Call Trace:
[ 2414.657776]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 2414.694825]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 2414.729268]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 2414.769847]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 2414.805628]  [<c1501477>] schedule+0x63/0x65
[ 2414.832453]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 2414.869475]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 2414.902581]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 2414.936769]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 2414.972268]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 2415.006395]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 2415.038491]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 2415.071052]  [<c11140f0>] update_time+0x1e/0x95
[ 2415.099609]  [<c111474d>] touch_atime+0xd1/0x105
[ 2415.131526]  [<c110f201>] iterate_dir+0x87/0x9f
[ 2415.160521]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 2415.191060]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 2415.218491]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 2535.351188] INFO: task mc:4759 blocked for more than 120 seconds.
[ 2535.390988]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 2535.435219] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2535.487488] mc              D c18d2600     0  4759   4568 0x00000084
[ 2535.526773]  f10f9e88 00000082 c18d2600 c18d2600 00000000 00000000 f3e38c80 00000000
[ 2535.577238]  ef34c490 00000e27 00000000 f10f9e58 c11d3ce9 00001000 00000002 00000000
[ 2535.624866]  00000e25 f10f9e64 c1062374 00000246 f10f9e74 00000246 f10f9e74 c150348b
[ 2535.673086] Call Trace:
[ 2535.689644]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 2535.726646]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 2535.827566]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 2535.918809]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 2535.958677]  [<c1501477>] schedule+0x63/0x65
[ 2535.987216]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 2536.026184]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 2536.059817]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 2536.094450]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 2536.132300]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 2536.173076]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 2536.205513]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 2536.240373]  [<c11140f0>] update_time+0x1e/0x95
[ 2536.270982]  [<c111474d>] touch_atime+0xd1/0x105
[ 2536.303949]  [<c110f201>] iterate_dir+0x87/0x9f
[ 2536.332996]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 2536.365792]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 2536.395033]  [<c1508c8d>] sysenter_do_call+0x12/0x28

-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Re: 3.13.5 kernel hangs some processes with btrfs

[Marc MERLIN]

On Sun, Feb 23, 2014 at 10:14:26PM -0800, Marc MERLIN wrote:
> Does someone know how I can debug further why this is hanging?
> 
> It seems that accessing a certain directory on one of my btrfs filesystems
> causes this.
> 
> The rest of my system seems ok, as long as I'm not touching this filesystem.
> 
> Is this a bug, or a performance problem?

Mmmh, this bug might be part of the problem:
gargamel:/mnt# btrfs scrub start btrfs_pool2
ERROR: scrub is already running.
To cancel use 'btrfs scrub cancel btrfs_pool2'.
To see the status use 'btrfs scrub status [-d] btrfs_pool2'.
gargamel:/mnt# btrfs scrub cancel btrfs_pool2
ERROR: scrub cancel failed on btrfs_pool2: not running
gargamel:/mnt# btrfs scrub status btrfs_pool2
scrub status for cb9df6d3-a528-4afc-9a45-4fed5ec358d6
        scrub started at Sun Feb 23 18:29:39 2014, running for 5 seconds
        total bytes scrubbed: 0.00 with 0 errors
gargamel:/mnt# btrfs scrub cancel btrfs_pool2
ERROR: scrub cancel failed on btrfs_pool2: not running
gargamel:/mnt# btrfs scrub status btrfs_pool2
scrub status for cb9df6d3-a528-4afc-9a45-4fed5ec358d6
        scrub started at Sun Feb 23 18:29:39 2014, running for 5 seconds
        total bytes scrubbed: 0.00 with 0 errors
gargamel:/mnt# 

Note that it says running for 5 seconds, but it started 4H ago.

Any idea what's going on here?

Marc
-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Re: 3.13.5 kernel hangs some processes with btrfs

[Wang Shilong]

On 02/24/2014 02:17 PM, Marc MERLIN wrote:
> On Sun, Feb 23, 2014 at 10:14:26PM -0800, Marc MERLIN wrote:
>> Does someone know how I can debug further why this is hanging?
>>
>> It seems that accessing a certain directory on one of my btrfs filesystems
>> causes this.
>>
>> The rest of my system seems ok, as long as I'm not touching this filesystem.
>>
>> Is this a bug, or a performance problem?
> Mmmh, this bug might be part of the problem:
> gargamel:/mnt# btrfs scrub start btrfs_pool2
> ERROR: scrub is already running.
> To cancel use 'btrfs scrub cancel btrfs_pool2'.
> To see the status use 'btrfs scrub status [-d] btrfs_pool2'.
> gargamel:/mnt# btrfs scrub cancel btrfs_pool2
> ERROR: scrub cancel failed on btrfs_pool2: not running
> gargamel:/mnt# btrfs scrub status btrfs_pool2
> scrub status for cb9df6d3-a528-4afc-9a45-4fed5ec358d6
>          scrub started at Sun Feb 23 18:29:39 2014, running for 5 seconds
>          total bytes scrubbed: 0.00 with 0 errors
> gargamel:/mnt# btrfs scrub cancel btrfs_pool2
> ERROR: scrub cancel failed on btrfs_pool2: not running
> gargamel:/mnt# btrfs scrub status btrfs_pool2
> scrub status for cb9df6d3-a528-4afc-9a45-4fed5ec358d6
>          scrub started at Sun Feb 23 18:29:39 2014, running for 5 seconds
>          total bytes scrubbed: 0.00 with 0 errors
> gargamel:/mnt#
>
> Note that it says running for 5 seconds, but it started 4H ago.
>
> Any idea what's going on here?
What is dmesg output?

Did it output something like "Skip abort transaction"? Also
what is your mount option? did you enable nodatasum etc?

Thanks,
Wang
>
> Marc

Re: 3.13.5 kernel hangs some processes with btrfs

[Duncan]

Marc MERLIN posted on Sun, 23 Feb 2014 22:17:14 -0800 as excerpted:

> Mmmh, this bug might be part of the problem:
> gargamel:/mnt# btrfs scrub start btrfs_pool2
> ERROR: scrub is already running.

> gargamel:/mnt# btrfs scrub cancel btrfs_pool2
> ERROR: scrub cancel failed on btrfs_pool2: not running

> gargamel:/mnt# btrfs scrub status
[snip output]
> Note that it says running for 5 seconds, but it started 4H ago.

This is a known issue.

I believe there's a fix coming (a cancel that blows away the tracking 
file if it finds it and no actual running scrub is the most obvious fix), 
but meanwhile, see the /var/lib/btrfs/scrub.status.* files.  That's where 
scrub state is stored, and manually blowing away the appropriate file 
should clear btrfs' memory of the aborted scrub, so you can scrub start 
properly.

-- 
Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman

Re: 3.13.5 kernel hangs some processes with btrfs

[Marc MERLIN]

On Mon, Feb 24, 2014 at 02:27:46PM +0800, Wang Shilong wrote:
> >Note that it says running for 5 seconds, but it started 4H ago.
> >
> >Any idea what's going on here?
> What is dmesg output?
> 
> Did it output something like "Skip abort transaction"? Also
> what is your mount option? did you enable nodatasum etc?

sh-4.1# btrfs scrub cancel /mnt/btrfs_pool2
ERROR: scrub cancel failed on /mnt/btrfs_pool2: not running
sh-4.1# 

And no, I get nothing in dmesg.

Now, what's very interesting is that I rebooted the machine, and even after
rebooting, scrub is still being shown as active on 3 of my devices.

sh-4.1# btrfs-scrub-status 
/mnt/btrfs_bigbackup
scrub status for 024ba4d0-dacb-438d-9f1b-eeb34083fe49
scrub device /dev/mapper/crypt_sdl1 (id 1) history
        scrub started at Sun Feb 23 21:32:32 2014 and finished after 262 seconds
        total bytes scrubbed: 2.76GiB with 0 errors
scrub device /dev/dm-6 (id 2) history
        scrub started at Sun Feb 23 21:32:32 2014 and finished after 249 seconds
        total bytes scrubbed: 2.82GiB with 0 errors
scrub device /dev/dm-5 (id 3) history
        scrub started at Sun Feb 23 21:32:32 2014 and finished after 246 seconds
        total bytes scrubbed: 2.82GiB with 0 errors
scrub device /dev/dm-7 (id 4) history
        scrub started at Sun Feb 23 21:32:32 2014 and finished after 260 seconds
        total bytes scrubbed: 2.75GiB with 0 errors
scrub device /dev/dm-8 (id 5) history
        scrub started at Sun Feb 23 21:32:32 2014 and finished after 257 seconds
        total bytes scrubbed: 2.75GiB with 0 errors
/mnt/btrfs_boot
scrub status for e4c1daa8-9c39-4a59-b0a9-86297d397f3b
scrub device /dev/mapper/cryptroot (id 1) history
        scrub started at Sun Feb 23 22:14:36 2014 and was aborted after 18 seconds
        total bytes scrubbed: 992.79MiB with 0 errors
/mnt/btrfs_pool1
scrub status for 6358304a-2234-4243-b02d-4944c9af47d7
scrub device /dev/mapper/dshelf1 (id 1) status
        scrub started at Sun Feb 23 06:50:46 2014, running for 11193 seconds
        total bytes scrubbed: 612.31GiB with 0 errors
/mnt/btrfs_pool2
scrub status for cb9df6d3-a528-4afc-9a45-4fed5ec358d6
scrub device /dev/mapper/dshelf2 (id 1) status
        scrub started at Sun Feb 23 18:29:39 2014, running for 5 seconds
        total bytes scrubbed: 0.00 with 0 errors
/mnt/btrfs_raid0
scrub status for 9f46dbe2-1344-44c3-b0fb-af2888c34f18
scrub device /dev/mapper/cryptraid0 (id 1) status
        scrub started at Sun Feb 23 09:56:57 2014, running for 25 seconds
        total bytes scrubbed: 964.86MiB with 0 errors
sh-4.1# 


sh-4.1# btrfs fi show
Label: btrfs_boot  uuid: e4c1daa8-9c39-4a59-b0a9-86297d397f3b
        Total devices 1 FS bytes used 60.83GiB
        devid    1 size 79.93GiB used 65.04GiB path /dev/mapper/cryptroot

Label: varlocalspace  uuid: 9f46dbe2-1344-44c3-b0fb-af2888c34f18
        Total devices 1 FS bytes used 772.80GiB
        devid    1 size 1.63TiB used 780.04GiB path /dev/mapper/cryptraid0

Label: btrfs_pool1  uuid: 6358304a-2234-4243-b02d-4944c9af47d7
        Total devices 1 FS bytes used 7.13TiB
        devid    1 size 14.55TiB used 7.50TiB path /dev/mapper/dshelf1

Label: btrfs_pool2  uuid: cb9df6d3-a528-4afc-9a45-4fed5ec358d6
        Total devices 1 FS bytes used 2.89TiB
        devid    1 size 7.28TiB used 2.96TiB path /dev/mapper/dshelf2

Label: bigbackup  uuid: 024ba4d0-dacb-438d-9f1b-eeb34083fe49
        Total devices 5 FS bytes used 30.01GiB
        devid    1 size 1.82TiB used 6.02GiB path /dev/mapper/crypt_sdl1
        devid    2 size 1.82TiB used 7.00GiB path /dev/dm-6
        devid    3 size 1.82TiB used 7.00GiB path /dev/dm-5
        devid    4 size 1.82TiB used 6.01GiB path /dev/dm-7
        devid    5 size 1.82TiB used 6.01GiB path /dev/dm-8

Btrfs v3.12
sh-4.1# 

Any other ideas?

Thanks,
Marc
-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Re: 3.13.5 kernel hangs some processes with btrfs

[Marc MERLIN]

On Mon, Feb 24, 2014 at 06:42:30AM +0000, Duncan wrote:
> I believe there's a fix coming (a cancel that blows away the tracking 
> file if it finds it and no actual running scrub is the most obvious fix), 
> but meanwhile, see the /var/lib/btrfs/scrub.status.* files.  That's where 
> scrub state is stored, and manually blowing away the appropriate file 
> should clear btrfs' memory of the aborted scrub, so you can scrub start 
> properly.

Ah, silly me, I thought this was all in the kernel and not in userspace.

Yep, I cleared the stats, and that part is back to ok, thanks.

I'm not getting btrfs hang on /mnt/btrfs_pool2 after reboot, so that's good.

But I'm still seeing these, albeit less often. 
Any idea what they could be linked to?
(I have a btrs send/receive going right now, it could hanging /mnt/btrfs_pool1
in a way that affects smbd, but the array feels ok otherwise, weird...)

[ 1332.548370] INFO: task smbd:21882 blocked for more than 120 seconds.
[ 1332.587455]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 1332.625478] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1332.673439] smbd            D c18d2600     0 21882   9962 0x00000080
[ 1332.713505]  ef78be88 00000086 c18d2600 c18d2600 c11e39bc 00002675 00000000 000000c5
[ 1332.761149]  f6e362d0 00000f16 00000000 ef78be58 c11d3ce9 00001000 00000002 00000000
[ 1332.808763]  00000f14 ef78be64 c1062374 00000246 ef78be74 00000246 ef78be74 c150348b
[ 1332.856382] Call Trace:
[ 1332.872106]  [<c11e39bc>] ? btrfs_tree_read_lock+0xb4/0xbc
[ 1332.906057]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 1332.942646]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 1332.976094]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 1333.013744]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 1333.048272]  [<c1501477>] schedule+0x63/0x65
[ 1333.074985]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 1333.111090]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 1333.140429]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 1333.172874]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 1333.206894]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 1333.239169]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 1333.270531]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 1333.302913]  [<c11140f0>] update_time+0x1e/0x95
[ 1333.331136]  [<c111474d>] touch_atime+0xd1/0x105
[ 1333.359834]  [<c110f201>] iterate_dir+0x87/0x9f
[ 1333.388016]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 1333.417730]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 1333.444837]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 1375.924436] nf_conntrack: automatic helper assignment is deprecated and it will be removed soon. Use the iptables CT target to attach helpers instead.
[ 1453.574620] INFO: task smbd:21882 blocked for more than 120 seconds.
[ 1453.613832]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 1453.652896] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1453.700923] smbd            D c18d2600     0 21882   9962 0x00000080
[ 1453.740164]  ef78be88 00000086 c18d2600 c18d2600 c11e39bc 00002675 00000000 000000c5
[ 1453.787879]  f6e362d0 00000f16 00000000 ef78be58 c11d3ce9 00001000 00000002 00000000
[ 1453.835604]  00000f14 ef78be64 c1062374 00000246 ef78be74 00000246 ef78be74 c150348b
[ 1453.883360] Call Trace:
[ 1453.899608]  [<c11e39bc>] ? btrfs_tree_read_lock+0xb4/0xbc
[ 1453.933661]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 1453.970338]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 1454.003890]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 1454.042674]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 1454.077390]  [<c1501477>] schedule+0x63/0x65
[ 1454.104194]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 1454.140351]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 1454.169714]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 1454.202140]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 1454.236090]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 1454.267416]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 1454.298728]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 1454.331069]  [<c11140f0>] update_time+0x1e/0x95
[ 1454.359214]  [<c111474d>] touch_atime+0xd1/0x105
[ 1454.388673]  [<c110f201>] iterate_dir+0x87/0x9f
[ 1454.416795]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 1454.446479]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 1454.473500]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 1574.608832] INFO: task smbd:21882 blocked for more than 120 seconds.
[ 1574.648653]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 1574.696703] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1574.745534] smbd            D c18d2600     0 21882   9962 0x00000084
[ 1574.785358]  ef78be88 00000086 c18d2600 c18d2600 c11e39bc 00002675 00000000 000000c5
[ 1574.833328]  f6e362d0 00000f16 00000000 ef78be58 c11d3ce9 00001000 00000002 00000000
[ 1574.881651]  00000f14 ef78be64 c1062374 00000246 ef78be74 00000246 ef78be74 c150348b
[ 1574.929217] Call Trace:
[ 1574.944894]  [<c11e39bc>] ? btrfs_tree_read_lock+0xb4/0xbc
[ 1574.978788]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 1575.015288]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 1575.048692]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 1575.087065]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 1575.122403]  [<c1501477>] schedule+0x63/0x65
[ 1575.149032]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 1575.185033]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 1575.214277]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 1575.246646]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 1575.280609]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 1575.311902]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 1575.343127]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 1575.375386]  [<c11140f0>] update_time+0x1e/0x95
[ 1575.403470]  [<c111474d>] touch_atime+0xd1/0x105
[ 1575.432043]  [<c110f201>] iterate_dir+0x87/0x9f
[ 1575.460837]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 1575.490433]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 1575.517402]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 1695.646996] INFO: task smbd:21882 blocked for more than 120 seconds.
[ 1695.686233]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 1695.724419] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1695.772929] smbd            D c18d2600     0 21882   9962 0x00000084
[ 1695.813545]  ef78be88 00000086 c18d2600 c18d2600 c11e39bc 00002675 00000000 000000c5
[ 1695.862111]  f6e362d0 00000f16 00000000 ef78be58 c11d3ce9 00001000 00000002 00000000
[ 1695.883936]  00000f14 ef78be64 c1062374 00000246 ef78be74 00000246 ef78be74 c150348b
[ 1695.883942] Call Trace:
[ 1695.883944]  [<c11e39bc>] ? btrfs_tree_read_lock+0xb4/0xbc
[ 1695.883951]  [<c11d3ce9>] ? map_private_extent_buffer+0x7e/0xa2
[ 1695.883954]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 1695.883958]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 1695.883961]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 1695.883966]  [<c1501477>] schedule+0x63/0x65
[ 1695.883969]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 1695.883973]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 1695.883999]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 1695.884003]  [<c11ba67b>] btrfs_join_transaction+0x18/0x1a
[ 1695.884005]  [<c11be973>] btrfs_dirty_inode+0x22/0x91
[ 1695.884009]  [<c11bea4b>] btrfs_update_time+0x69/0x75
[ 1695.884011]  [<c11be9e2>] ? btrfs_dirty_inode+0x91/0x91
[ 1695.884014]  [<c11140f0>] update_time+0x1e/0x95
[ 1695.884217]  [<c111474d>] touch_atime+0xd1/0x105
[ 1695.884219]  [<c110f201>] iterate_dir+0x87/0x9f
[ 1695.884221]  [<c110f65f>] SyS_getdents64+0x65/0xbb
[ 1695.884223]  [<c110f3d9>] ? filldir+0xdf/0xdf
[ 1695.884225]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[ 1695.884420] INFO: task sync:31933 blocked for more than 120 seconds.
[ 1695.884421]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[ 1695.884422] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1695.884423] sync            D c18d2600     0 31933  31598 0x00000080
[ 1695.884425]  c30f3ee4 00000086 c18d2600 c18d2600 00011d30 00000000 00000000 00000153
[ 1695.884429]  f6f90150 00000000 00000000 f1e8a070 c30f3eb0 c11cde6b 00000000 c30f3eb4
[ 1695.884432]  c150345e c30f3ec0 c1062374 00000246 c30f3ed0 00000246 c30f3ed0 c150348b
[ 1695.884436] Call Trace:
[ 1695.884436]  [<c11cde6b>] ? find_first_extent_bit_state+0x13/0x3f
[ 1695.884608]  [<c150345e>] ? _raw_spin_unlock+0x15/0x26
[ 1695.884609]  [<c1062374>] ? arch_local_irq_save+0x12/0x17
[ 1695.884611]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[ 1695.884613]  [<c105e6d6>] ? prepare_to_wait_event+0x85/0xb6
[ 1695.884615]  [<c1501477>] schedule+0x63/0x65
[ 1695.884617]  [<c11b9288>] wait_current_trans.isra.14+0x7e/0xcb
[ 1695.884619]  [<c105e774>] ? finish_wait+0x4e/0x4e
[ 1695.884621]  [<c11ba35c>] start_transaction+0x21f/0x4f0
[ 1695.884623]  [<c11ba6e7>] btrfs_attach_transaction_barrier+0x1c/0x41
[ 1695.884625]  [<c11995fb>] btrfs_sync_fs+0x67/0xa5
[ 1695.884628]  [<c1199594>] ? ftrace_raw_event_btrfs_space_reservation+0xe2/0xe2
[ 1695.884630]  [<c11225af>] ? SyS_tee+0x1e1/0x1e1
[ 1695.884633]  [<c11225cb>] sync_fs_one_sb+0x1c/0x1e
[ 1695.884635]  [<c1104c23>] iterate_supers+0x5b/0xa0
[ 1695.884637]  [<c1122996>] sys_sync+0x54/0x7e
[ 1695.884638]  [<c1508c8d>] sysenter_do_call+0x12/0x28

Marc
-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Re: 3.13.5 kernel hangs some processes with btrfs

[Wang Shilong]

On 02/24/2014 02:58 PM, Marc MERLIN wrote:
> On Mon, Feb 24, 2014 at 06:42:30AM +0000, Duncan wrote:
>> I believe there's a fix coming (a cancel that blows away the tracking
>> file if it finds it and no actual running scrub is the most obvious fix),
>> but meanwhile, see the /var/lib/btrfs/scrub.status.* files.  That's where
>> scrub state is stored, and manually blowing away the appropriate file
>> should clear btrfs' memory of the aborted scrub, so you can scrub start
>> properly.
> Ah, silly me, I thought this was all in the kernel and not in userspace.
>
> Yep, I cleared the stats, and that part is back to ok, thanks.
>
> I'm not getting btrfs hang on /mnt/btrfs_pool2 after reboot, so that's good.
>
> But I'm still seeing these, albeit less often.
> Any idea what they could be linked to?
> (I have a btrs send/receive going right now, it could hanging /mnt/btrfs_pool1

I noticed  scrub for /mnt/btrfs_pool1 is running more than 10000s....

Not sure if it is related to send/receive, but if you are still runing 
send/receive,
just terminate it and let's see if things will become better.

Also Josef gave a patch that can speed up send/receive a lot which has been
pused into btrfs-next, you can try it.

Thanks,
Wang
> in a way that affects smbd, but the array feels ok otherwise, weird...)
>   

Re: 3.13.5 kernel hangs some processes with btrfs

[Duncan]

Marc MERLIN posted on Sun, 23 Feb 2014 22:58:47 -0800 as excerpted:

> On Mon, Feb 24, 2014 at 06:42:30AM +0000, Duncan wrote:
>> [S]ee the /var/lib/btrfs/scrub.status.* files.  That's
>> where scrub state is stored, and manually blowing away the appropriate
>> file should clear btrfs' memory of the aborted scrub, so you can scrub
>> start properly.
> 
> Ah, silly me, I thought this was all in the kernel and not in userspace.

That was a bit eye opening for me too. =:^)

> Yep, I cleared the stats, and that part is back to ok, thanks.

=:^)

> But I'm still seeing these, albeit less often.
> Any idea what they could be linked to?
> (I have a btrs send/receive going right now, it could hanging
> /mnt/btrfs_pool1 in a way that affects smbd, but the array feels ok
> otherwise, weird...)
> 
> [ 1332.548370] INFO: task smbd:21882 blocked for more than 120 seconds.
> [ 1332.587455]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
> [ 1332.625478] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.

I've not seen anything like that here, but there are several kernel 
3.13/3.14-rc reports of similar behavior on the list.

>From what I've seen reported, the problem /might/ be large-internal-write-
file related, multi-gig vm images, database files, etc, actively being 
written, the sort of thing NOCOW *SHOULD* fix, at least in the absence of 
frequent snapshots, but in at least one case, NOCOW had been properly 
activated before the file content was written and the user was NOT doing 
major snapshotting of any kind, so that rules out those triggers.

So I've no idea, except that in every reported case I've seen, people did 
have large VMs or the like going as well, so that's a possible connection 
despite the above.

Hopefully the devs are having more success at assembling this puzzle than 
I am, but I've no suggestions for fixing it ATM, except the possibility 
of putting your VMs, etc, on a dedicated non-btrfs filesystem for the 
time being, assuming of course that apparent connection is a valid one.

-- 
Duncan - List replies preferred.   No HTML msgs.
"Every nonfree program has a lord, a master --
and if you use the program, he is your master."  Richard Stallman

Re: 3.13.5 kernel hangs some processes with btrfs

[Marc MERLIN]

On Mon, Feb 24, 2014 at 07:29:58AM +0000, Duncan wrote:
> > But I'm still seeing these, albeit less often.
> > Any idea what they could be linked to?
> > (I have a btrs send/receive going right now, it could hanging
> > /mnt/btrfs_pool1 in a way that affects smbd, but the array feels ok
> > otherwise, weird...)
> > 
> > [ 1332.548370] INFO: task smbd:21882 blocked for more than 120 seconds.
> > [ 1332.587455]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
> > [ 1332.625478] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables this message.
> 
> I've not seen anything like that here, but there are several kernel 
> 3.13/3.14-rc reports of similar behavior on the list.
 
I'll have to try this. Interestingly, I just got the following overnight.

Something killed 3 different drives from software raid arrays, and the
drives are all fine.

It looks like btrfs hung my kernel hard enough that it messed up
software raid, killed my array on which btrfs was, and then caused a
cascade of further btrfs failures.
Are those 2 traces useful?

Many of these errors:
[23721.563736] BUG: soft lockup - CPU#0 stuck for 22s! [btrfs:6140]
[23721.601096] Modules linked in:[23721.601096] Modules linked in: ip6table_filter ip6table_filter ip6_tables ip6_tables ebtable_nat ebtable_nat ebtables ebtables tun tun ppdev ppdev lp lp autofs4 autofs4 binfmt_misc binfmt_misc kl5kusb105 kl5kusb105 deflate deflate ctr ctr twofish_generic twofish_generic twofish_common twofish_common camellia_generic camellia_generic serpent_generic serpent_generic blowfish_generic blowfish_generic blowfish_common blowfish_common cast5_generic cast5_generic cast_common cast_common ftdi_sio ftdi_sio des_generic des_generic keyspan keyspan cmac cmac xcbc xcbc rmd160 rmd160 sha512_generic sha512_generic crypto_null crypto_null af_key af_key xfrm_algo xfrm_algo dm_mirror dm_mirror dm_region_hash dm_region_hash dm_log dm_log nfsd nfsd nfs_acl nfs_acl auth_rpcgss auth_rpcgss nfs nfs fscache fscache lockd lockd sunrpc sunrpc ipt_REJECT ipt_REJECT xt_conntrack xt_conntrack xt_nat xt_nat xt_tcpudp xt_tcpudp xt_LOG xt_LOG iptable_mangle iptable_mangle iptable_filter iptable_filter fuse fuse lm85 lm85 hwmon_vid hwmon_vid dm_snapshot dm_snapshot iptable_nat iptable_nat ip_tables ip_tables nf_conntrack_ipv4 nf_conntrack_ipv4 nf_defrag_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat_ipv4 nf_conntrack_ftp nf_conntrack_ftp ipt_MASQUERADE ipt_MASQUERADE nf_nat nf_nat x_tables x_tables nf_conntrack nf_conntrack sg sg st st snd_pcm_oss snd_pcm_oss snd_mixer_oss snd_mixer_oss snd_cmipci snd_cmipci gameport gameport microcode microcode snd_opl3_lib snd_opl3_lib snd_mpu401_uart snd_mpu401_uart kvm_intel kvm_intel snd_seq_midi snd_seq_midi kvm kvm eeepc_wmi eeepc_wmi snd_seq_midi_event snd_seq_midi_event rc_ati_x10 rc_ati_x10 asus_wmi asus_wmi ati_remote ati_remote snd_seq snd_seq sparse_keymap sparse_keymap coretemp coretemp asix asix snd_rawmidi snd_rawmidi snd_hda_codec_realtek snd_hda_codec_realtek parport_pc parport_pc libphy libphy intel_rapl intel_rapl rfkill rfkill parport parport pl2303 pl2303 x86_pkg_temp_thermal x86_pkg_temp_thermal snd_seq_device snd_seq_device intel_powerclamp intel_powerclamp rc
_core rc_core usbnet usbnet wmi wmi ezusb ezusb tpm_tis tpm_tis tpm tpm pcspkr pcspkr usbserial usbserial snd_hda_intel snd_hda_intel evdev evdev snd_hda_codec snd_hda_codec i2c_i801 i2c_i801 snd_hwdep snd_hwdep snd_pcm snd_pcm snd_timer snd_timer processor processor lpc_ich lpc_ich xhci_hcd xhci_hcd snd snd soundcore soundcore snd_page_alloc snd_page_alloc xts xts gf128mul gf128mul dm_crypt dm_crypt dm_mod dm_mod raid456 raid456 async_raid6_recov async_raid6_recov async_pq async_pq async_xor async_xor async_memcpy async_memcpy async_tx async_tx e1000e e1000e ptp ptp pps_core pps_core ehci_pci ehci_pci r8169 r8169 ehci_hcd ehci_hcd sata_sil24 sata_sil24 sata_mv sata_mv thermal thermal mii mii crc32_pclmul crc32_pclmul crc32c_intel crc32c_intel fan fan usbcore usbcore usb_common usb_common [last unloaded: kl5kusb105] [last unloaded: kl5kusb105]
[23722.377527] CPU: 0 PID: 6140 Comm: btrfs Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
[23722.427962] Hardware name: System manufacturer System Product Name/P8H67-M PRO, BIOS 3806 08/20/2012
[23722.484154] task: f1a00510 ti: c6f84000 task.ti: c6f84000
[23722.517991] EIP: 0060:[<c119e324>] EFLAGS: 00000282 CPU: 0
[23722.552341] EIP is at btrfs_comp_cpu_keys+0x6/0x72
[23722.582497] EAX: c6f85cc7 EBX: 00000000 ECX: 00000d41 EDX: c6f85e05
[23722.621532] ESI: 00000000 EDI: 00000258 EBP: c6f85cbc ESP: c6f85cb0
[23722.660543]  DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[23722.694331] CR0: 80050033 CR2: b754df59 CR3: 2d7a5000 CR4: 000407d0
[23722.733354] Stack:
[23722.746819]  00000000[23722.746819]  00000000 00000000 00000000 00000258 00000258 c6f85cdc c6f85cdc c119e3c1 c119e3c1 410002bd 410002bd 0000000d 0000000d 6c000000 6c000000
[23722.794851]  00100000[23722.794851]  00100000 00000000 00000000 000002bd 000002bd c6f85d24 c6f85d24 c119e47d c119e47d c6f85e05 c6f85e05 00000019 00000019 00000018 00000018
[23722.842884]  c9c677d0[23722.842884]  c9c677d0 00000018 00000018 c7728000 c7728000 00000000 00000000 00001000 00001000 dfaca800 dfaca800 c6f85d2c c6f85d2c c1054429 c1054429
[23722.890935] Call Trace:
[23722.907058]  [<c119e3c1>] comp_keys+0x31/0x37
[23722.934655]  [<c119e47d>] generic_bin_search.constprop.24+0xb6/0xf5
[23722.973703]  [<c1054429>] ? try_to_wake_up+0x176/0x180
[23723.005987]  [<c119e4fa>] bin_search+0x3e/0x48
[23723.034114]  [<c119fd16>] btrfs_search_slot+0x22b/0x59c
[23723.066926]  [<c1104989>] ? __sb_start_write+0x86/0xb3
[23723.099195]  [<c11a2028>] btrfs_search_slot_for_read+0x32/0xc9
[23723.135657]  [<c1208a6e>] btrfs_ioctl_send+0x6c6/0x8a5
[23723.167948]  [<c10c77aa>] ? __rmqueue+0x7f/0x241
[23723.197116]  [<c11e144b>] ? update_ioctl_balance_args+0xde/0xde
[23723.234097]  [<c11e2a06>] btrfs_ioctl+0x15bb/0x23a5
[23723.264824]  [<c1005daf>] ? __cycles_2_ns+0x19/0x78
[23723.295550]  [<c1006318>] ? native_sched_clock+0x3a/0x3d
[23723.328862]  [<c1005c8f>] ? paravirt_sched_clock+0x9/0xd
[23723.362189]  [<c1005daf>] ? __cycles_2_ns+0x19/0x78
[23723.392889]  [<c10584ab>] ? update_rq_runnable_avg+0x1f0/0x1f8
[23723.429328]  [<c105788f>] ? hrtick_update+0x17/0x42
[23723.460037]  [<c11e144b>] ? update_ioctl_balance_args+0xde/0xde
[23723.497023]  [<c110f0d1>] do_vfs_ioctl+0x3d9/0x417
[23723.527188]  [<c110f0d1>] ? do_vfs_ioctl+0x3d9/0x417
[23723.558335]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[23723.596240]  [<c10508ae>] ? task_rq_unlock+0x1b/0x1f
[23723.627346]  [<c1109340>] ? path_put+0x1a/0x1d
[23723.655279]  [<c110f159>] SyS_ioctl+0x4a/0x6b
[23723.682661]  [<c1508c8d>] sysenter_do_call+0x12/0x28
[23723.713642] Code:[23723.713642] Code: 8b 8b 45 45 dc dc 85 85 c0 c0 74 74 14 14 8b 8b 75 75 cc cc 39 39 06 06 74 74 05 05 e8 e8 d8 d8 5a 5a 04 04 00 00 8b 8b 45 45 dc dc e8 e8 46 46 48 48 03 03 00 00 89 89 f8 f8 8d 8d 65 65 f4 f4 5b 5b 5e 5e 5f 5f 5d 5d c3 c3 55 55 89 89 e5 e5 57 57 56 56 53 53 <66> <66> 66 66 66 66 66 66 90 90 8b 8b 78 78 04 04 8b 8b 72 72 04 04 8b 8b 18 18 8b 8b 0a 0a 39 39 f7 f7 77 77 4d 4d 72 72 46 46

Then eventually this:
[34474.730456] NMI backtrace for cpu 2
[34474.730458] CPU: 2 PID: 697 Comm: md8_raid5 Tainted: G        W    3.13.5-ia32-i915-preempt-20140216 #1
[34474.730459] Hardware name: System manufacturer System Product Name/P8H67-M PRO, BIOS 3806 08/20/2012
[34474.730461] task: f3cee090 ti: f2f76000 task.ti: f2f76000
[34474.730462] EIP: 0060:[<c1029222>] EFLAGS: 00000002 CPU: 2
[34474.730465] EIP is at early_serial_putc+0x1a/0x33
[34474.730467] EAX: 00000000 EBX: 000003f8 ECX: 0000ffe3 EDX: 000003fd
[34474.730468] ESI: 00000020 EDI: 00000006 EBP: f2f77c04 ESP: f2f77bfc
[34474.730470]  DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[34474.730471] CR0: 80050033 CR2: b774b000 CR3: 09bc4000 CR4: 000407d0
[34474.730472] Stack:
[34474.730477]  c18eb911 c18eb939 f2f77c14 c102925e c17cd3ec 00000059 f2f77c28 c106adc3
[34474.730481]  c19017ac 00000006 00000059 f2f77c5c c106b971 c18eb8e0 00000400 00015250
[34474.730485]  c150348b 0001b51f 00000000 00000001 00000086 00000052 00000001 00000000
[34474.730486] Call Trace:
[34474.730489]  [<c102925e>] early_serial_write+0x23/0x31
[34474.730492]  [<c106adc3>] call_console_drivers.constprop.6+0x91/0xb9
[34474.730495]  [<c106b971>] console_unlock+0x286/0x324
[34474.730497]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[34474.730500]  [<c106bd9a>] vprintk_emit+0x38b/0x3b2
[34474.730503]  [<c1051521>] ? finish_task_switch+0x70/0xa1
[34474.730506]  [<c14fb213>] printk+0x1c/0x1e
[34474.730509]  [<c11d4c69>] btrfs_dev_stat_print_on_error+0x62/0x72
[34474.730512]  [<c11d4d04>] btrfs_end_bio+0x8b/0xf4
[34474.730516]  [<c1126e78>] bio_endio+0x2a/0x2c
[34474.730526]  [<f88e60de>] dec_pending+0x268/0x294 [dm_mod]
[34474.730534]  [<f88e6902>] clone_endio+0x7b/0x83 [dm_mod]
[34474.730537]  [<c1126e78>] bio_endio+0x2a/0x2c
[34474.730543]  [<f856933e>] crypt_dec_pending+0x48/0x65 [dm_crypt]
[34474.730548]  [<f8569766>] crypt_endio+0x88/0x8e [dm_crypt]
[34474.730553]  [<f85696de>] ? crypt_free_buffer_pages.isra.10+0x44/0x44 [dm_crypt]
[34474.730556]  [<c1126e78>] bio_endio+0x2a/0x2c
[34474.730563]  [<f8883eb6>] return_io+0x3b/0x45 [raid456]
[34474.730570]  [<f888a3ee>] handle_stripe+0x1e34/0x1e79 [raid456]
[34474.730579]  [<f888a677>] handle_active_stripes.isra.23+0x244/0x2b8 [raid456]
[34474.730586]  [<f888a677>] ? handle_active_stripes.isra.23+0x244/0x2b8 [raid456]
[34474.730592]  [<f8884054>] ? __release_stripe+0x2d/0x32 [raid456]
[34474.730599]  [<f888a9aa>] raid5d+0x2bf/0x3ca [raid456]
[34474.730606]  [<f888a9aa>] ? raid5d+0x2bf/0x3ca [raid456]
[34474.730609]  [<c10217f1>] ? smp_reschedule_interrupt+0x19/0x1b
[34474.730612]  [<c1501477>] ? schedule+0x63/0x65
[34474.730615]  [<c150348b>] ? _raw_spin_unlock_irqrestore+0x1c/0x2d
[34474.730618]  [<c141a1d5>] md_thread+0xed/0x104
[34474.730620]  [<c141a1d5>] ? md_thread+0xed/0x104
[34474.730623]  [<c105e774>] ? finish_wait+0x4e/0x4e
[34474.730625]  [<c141a0e8>] ? bb_store+0x4b/0x4b
[34474.730627]  [<c10496d4>] kthread+0x8d/0x92
[34474.730630]  [<c1508bf7>] ret_from_kernel_thread+0x1b/0x28
[34474.730633]  [<c1049647>] ? __kthread_parkme+0x55/0x55
[34474.730658] Code: 3b 75 e8 0f 85 1c ff ff ff 83 c4 0c 5b 5e 5f 5d c3 55 b9 ff ff 00 00 89 e5 56 89 c6 53 eb 02 f3 90 8b 1d 24 d4 7c c1 8d 53 05 ec <a8> 20 75 03 49 75 ed 89 f0 89 da ee 5b 31 c0 85 c9 0f 94 c0 f7


and plenty of those after that.
[34223.863987] btrfs: bdev /dev/mapper/dshelf2 errs: wr 13, rd 5692324, flush 0, corrupt 0, gen 0
[34228.450714] btrfs_dev_stat_print_on_error: 17000 callbacks suppressed
[34228.658914] btrfs: bdev /dev/mapper/dshelf2 errs: wr 13, rd 5709325, flush 0, corrupt 0, gen 0
[34228.658914] btrfs: bdev /dev/mapper/dshelf2 errs: wr 13, rd 5709325, flush 0, corrupt 0, gen 0
[34228.763017] btrfs: bdev /dev/mapper/dshelf2 errs: wr 13, rd 5709326, flush 0, corrupt 0, gen 0
[34230.564858] btrfs: bdev /dev/mapper/dshelf2 errs: wr 13, rd 5709327, flush 0, corrupt 0, gen 0
[34230.617159] btrfs: bdev /dev/mapper/dshelf2 errs: wr 13, rd 5709328, flush 0, corrupt 0, gen 0
[34230.684634] btrfs: bdev /dev/mapper/dshelf2 errs: wr 13, rd 5709329, flush 0, corrupt 0, gen 0
[34230.736985] btrfs: bdev /dev/mapper/dshelf2 errs: wr 13, rd 5709330, flush 0, corrupt 0, gen 0


-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/                         | PGP 1024R/763BE901

Re: 3.14rc3 kernel also hangs some processes with btrfs

[Marc MERLIN]

On Mon, Feb 24, 2014 at 09:35:19AM -0800, Marc MERLIN wrote:
> On Mon, Feb 24, 2014 at 07:29:58AM +0000, Duncan wrote:
> > > But I'm still seeing these, albeit less often.
> > > Any idea what they could be linked to?
> > > (I have a btrs send/receive going right now, it could hanging
> > > /mnt/btrfs_pool1 in a way that affects smbd, but the array feels ok
> > > otherwise, weird...)
> > > 
> > > [ 1332.548370] INFO: task smbd:21882 blocked for more than 120 seconds.
> > > [ 1332.587455]       Not tainted 3.13.5-ia32-i915-preempt-20140216 #1
> > > [ 1332.625478] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > > disables this message.
> > 
> > I've not seen anything like that here, but there are several kernel 
> > 3.13/3.14-rc reports of similar behavior on the list.
>  
> I'll have to try this. Interestingly, I just got the following overnight.
> 
> Something killed 3 different drives from software raid arrays, and the
> drives are all fine.
> 
> It looks like btrfs hung my kernel hard enough that it messed up
> software raid, killed my array on which btrfs was, and then caused a
> cascade of further btrfs failures.
> Are those 2 traces useful?

I upgraded to 3.14rc3  and I'm also seeing hangs, although not as severe

To answer earlier questions:
1) the filesystem I'm copying is brand new, I just created it
2) files were contiguous and not being written randomly (mp3s)

Here are the logs:

[  381.512765] BTRFS: device label bigbackup devid 3 transid 179 /dev/dm-5
[  382.875847] BTRFS: device label bigbackup devid 2 transid 179 /dev/dm-6
[  384.795334] BTRFS: device label bigbackup devid 4 transid 179 /dev/dm-7
[  387.265961] BTRFS: device label bigbackup devid 5 transid 179 /dev/dm-8
[  389.904834] BTRFS: device label bigbackup devid 1 transid 179 /dev/dm-9
[  390.054771] BTRFS: device label bigbackup devid 3 transid 179 /dev/mapper/crypt_sdo1
[  390.107006] BTRFS: device label bigbackup devid 3 transid 179 /dev/dm-5
[  390.129071] BTRFS: device label bigbackup devid 2 transid 179 /dev/mapper/crypt_sdn1
[  390.177737] BTRFS: device label bigbackup devid 2 transid 179 /dev/dm-6
[  390.221597] BTRFS: device label bigbackup devid 4 transid 179 /dev/mapper/crypt_sdp1
[  390.291095] BTRFS: device label bigbackup devid 1 transid 179 /dev/mapper/crypt_sdm1
[  390.334910] BTRFS: device label bigbackup devid 1 transid 179 /dev/dm-9
[  390.357362] BTRFS: device label bigbackup devid 4 transid 179 /dev/dm-7
[  390.378629] BTRFS: device label bigbackup devid 5 transid 179 /dev/mapper/crypt_sdq1
[  390.441157] BTRFS: device label bigbackup devid 1 transid 179 /dev/mapper/crypt_sdm1
[  390.468279] BTRFS info (device dm-9): disk space caching is enabled
[  390.476577] BTRFS: device label bigbackup devid 5 transid 179 /dev/dm-8
[  725.501091] INFO: task btrfs-transacti:3218 blocked for more than 120 seconds.
[  725.529118]       Not tainted 3.14.0-rc3 #1
[  725.542713] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  725.567489] btrfs-transacti D ffff88020d5fa880     0  3218      2 0x00000000
[  725.591645]  ffff88020cad3dc8 0000000000000046 ffff88020cad3fd8 ffff88020d5fa350
[  725.616304]  00000000000141c0 ffff88020d5fa350 ffff8801a5ed82a0 ffff8801a5ed8310
[  725.640545]  ffff8801a5ed82a0 ffff8801a5ed82a0 0000000000000000 ffff88020cad3dd8
[  725.665227] Call Trace:
[  725.674397]  [<ffffffff8160b059>] schedule+0x73/0x75
[  725.690761]  [<ffffffff81229973>] wait_for_commit.isra.10+0x50/0x67
[  725.711610]  [<ffffffff81085062>] ? finish_wait+0x65/0x65
[  725.729355]  [<ffffffff8122acd8>] btrfs_commit_transaction+0x143/0x849
[  725.750238]  [<ffffffff81227598>] transaction_kthread+0xf8/0x1ab
[  725.769867]  [<ffffffff812274a0>] ? btrfs_cleanup_transaction+0x43f/0x43f
[  725.791465]  [<ffffffff8106bc1b>] kthread+0xae/0xb6
[  725.807384]  [<ffffffff8106bb6d>] ? __kthread_parkme+0x61/0x61
[  725.826176]  [<ffffffff8161413c>] ret_from_fork+0x7c/0xb0
[  725.843645]  [<ffffffff8106bb6d>] ? __kthread_parkme+0x61/0x61
[  845.962068] INFO: task btrfs-transacti:3218 blocked for more than 120 seconds.
[  845.986941]       Not tainted 3.14.0-rc3 #1
[  846.000617] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.025730] btrfs-transacti D ffff88020d5fa880     0  3218      2 0x00000000
[  846.048610]  ffff88020cad3dc8 0000000000000046 ffff88020cad3fd8 ffff88020d5fa350
[  846.072100]  00000000000141c0 ffff88020d5fa350 ffff8801a5ed82a0 ffff8801a5ed8310
[  846.095559]  ffff8801a5ed82a0 ffff8801a5ed82a0 0000000000000000 ffff88020cad3dd8
[  846.119008] Call Trace:
[  846.127440]  [<ffffffff8160b059>] schedule+0x73/0x75
[  846.144015]  [<ffffffff81229973>] wait_for_commit.isra.10+0x50/0x67
[  846.164512]  [<ffffffff81085062>] ? finish_wait+0x65/0x65
[  846.182412]  [<ffffffff8122acd8>] btrfs_commit_transaction+0x143/0x849
[  846.203734]  [<ffffffff81227598>] transaction_kthread+0xf8/0x1ab
[  846.223484]  [<ffffffff812274a0>] ? btrfs_cleanup_transaction+0x43f/0x43f
[  846.245587]  [<ffffffff8106bc1b>] kthread+0xae/0xb6
[  846.261992]  [<ffffffff8106bb6d>] ? __kthread_parkme+0x61/0x61
[  846.281143]  [<ffffffff8161413c>] ret_from_fork+0x7c/0xb0
[  846.299126]  [<ffffffff8106bb6d>] ? __kthread_parkme+0x61/0x61
[  966.418867] INFO: task btrfs-transacti:3218 blocked for more than 120 seconds.
[  966.442696]       Not tainted 3.14.0-rc3 #1
[  966.457407] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  966.483016] btrfs-transacti D ffff88020d5fa880     0  3218      2 0x00000000
[  966.506440]  ffff88020cad3dc8 0000000000000046 ffff88020cad3fd8 ffff88020d5fa350
[  966.530916]  00000000000141c0 ffff88020d5fa350 ffff8801a5ed82a0 ffff8801a5ed8310
[  966.555390]  ffff8801a5ed82a0 ffff8801a5ed82a0 0000000000000000 ffff88020cad3dd8
[  966.579921] Call Trace:
[  966.589422]  [<ffffffff8160b059>] schedule+0x73/0x75
[  966.606433]  [<ffffffff81229973>] wait_for_commit.isra.10+0x50/0x67
[  966.627339]  [<ffffffff81085062>] ? finish_wait+0x65/0x65
[  966.645553]  [<ffffffff8122acd8>] btrfs_commit_transaction+0x143/0x849
[  966.667268]  [<ffffffff81227598>] transaction_kthread+0xf8/0x1ab
[  966.687403]  [<ffffffff812274a0>] ? btrfs_cleanup_transaction+0x43f/0x43f
[  966.709881]  [<ffffffff8106bc1b>] kthread+0xae/0xb6
[  966.726630]  [<ffffffff8106bb6d>] ? __kthread_parkme+0x61/0x61
[  966.746227]  [<ffffffff8161413c>] ret_from_fork+0x7c/0xb0
[  966.764083]  [<ffffffff8106bb6d>] ? __kthread_parkme+0x61/0x61
[ 1086.879792] INFO: task btrfs-transacti:3218 blocked for more than 120 seconds.
[ 1086.903594]       Not tainted 3.14.0-rc3 #1
[ 1086.918322] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1086.943833] btrfs-transacti D ffff88020d5fa880     0  3218      2 0x00000000
[ 1086.967139]  ffff88020cad3dc8 0000000000000046 ffff88020cad3fd8 ffff88020d5fa350
[ 1086.991476]  00000000000141c0 ffff88020d5fa350 ffff8801a5ed82a0 ffff8801a5ed8310
[ 1087.015821]  ffff8801a5ed82a0 ffff8801a5ed82a0 0000000000000000 ffff88020cad3dd8
[ 1087.039461] Call Trace:
[ 1087.048083]  [<ffffffff8160b059>] schedule+0x73/0x75
[ 1087.064249]  [<ffffffff81229973>] wait_for_commit.isra.10+0x50/0x67
[ 1087.084318]  [<ffffffff81085062>] ? finish_wait+0x65/0x65
[ 1087.101780]  [<ffffffff8122acd8>] btrfs_commit_transaction+0x143/0x849
[ 1087.122610]  [<ffffffff81227598>] transaction_kthread+0xf8/0x1ab
[ 1087.141906]  [<ffffffff812274a0>] ? btrfs_cleanup_transaction+0x43f/0x43f
[ 1087.163541]  [<ffffffff8106bc1b>] kthread+0xae/0xb6
[ 1087.179446]  [<ffffffff8106bb6d>] ? __kthread_parkme+0x61/0x61
[ 1087.198812]  [<ffffffff8161413c>] ret_from_fork+0x7c/0xb0
[ 1087.216988]  [<ffffffff8106bb6d>] ? __kthread_parkme+0x61/0x61
[ 1693.760950] perf samples too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
[ 1693.789603] INFO: NMI handler (perf_event_nmi_handler) took too long to run: 28.656 msecs

My btrfs copy is working now, without hangs, but 2mn hangs on the above is still bad, especially
on a brand new filesystem.

Marc
-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/                         | PGP 1024R/763BE901