btrfs hung tasks

btrfs hung tasks

[John Drescher]

I am trying to debug this problem since it appears this is causing
mythtv to truncate recordings on top of other very long delays.

 # uname -a
Linux jmd0.comcast.net 3.11.4-gentoo-jmd0 #1 SMP PREEMPT Mon Oct 7
21:04:44 EDT 2013 x86_64 Intel(R) Core(TM)2 Quad CPU Q9550 @ 2.83GHz
GenuineIntel GNU/Linux

Here is 1 example of a hung task:

[ 3000.576427] INFO: task TFWWrite:11329 blocked for more than 120 seconds.
[ 3000.576430] "echo 0 > /proc/sys/kernel/hung_task_
timeout_secs" disables this message.
[ 3000.576433] TFWWrite        D ffff8800a7ab5ac0     0 11329      1 0x00000000
[ 3000.576437]  ffff8800a7ab5a18 0000000000000082 0000000000000002
ffff8800a7ab5fd8
[ 3000.576442]  ffff8800a7ab5fd8 0000000000004000 ffff8801a6cfade0
ffff880099782de0
[ 3000.576445]  0000000000000000 00000000000000d3 00000000000001a6
0000000000000001
[ 3000.576449] Call Trace:
[ 3000.576458]  [<ffffffff81074bfe>] ? load_balance+0xfe/0x800
[ 3000.576462]  [<ffffffff8106e975>] ? sched_clock_local+0x25/0xa0
[ 3000.576466]  [<ffffffff810d89e0>] ? __lock_page+0x70/0x70
[ 3000.576471]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3000.576474]  [<ffffffff8156073a>] io_schedule+0x8a/0xd0
[ 3000.576477]  [<ffffffff810d89e9>] sleep_on_page+0x9/0x10
[ 3000.576480]  [<ffffffff8155e133>] __wait_on_bit_lock+0x53/0xb0
[ 3000.576484]  [<ffffffff810d89d2>] __lock_page+0x62/0x70
[ 3000.576488]  [<ffffffff810603c0>] ? wake_atomic_t_function+0x30/0x30
[ 3000.576492]  [<ffffffff810d8b71>] find_lock_page+0x51/0x80
[ 3000.576495]  [<ffffffff810d948a>] find_or_create_page+0x3a/0xc0
[ 3000.576499]  [<ffffffff8128443c>] prepare_pages.isra.23+0x18c/0x340
[ 3000.576504]  [<ffffffff81255990>] ? block_rsv_add_bytes+0x50/0x70
[ 3000.576508]  [<ffffffff81284fca>] __btrfs_buffered_write+0x29a/0x4e0
[ 3000.576511]  [<ffffffff81285425>] btrfs_file_aio_write+0x215/0x580
[ 3000.576515]  [<ffffffff8111b30e>] ? kmem_cache_free+0xae/0x180
[ 3000.576519]  [<ffffffff8113a4a1>] ? final_putname+0x21/0x50
[ 3000.576523]  [<ffffffff8112eb1b>] do_sync_write+0x7b/0xb0
[ 3000.576527]  [<ffffffff8112f8f0>] vfs_write+0xc0/0x1f0
[ 3000.576530]  [<ffffffff8112fded>] SyS_write+0x4d/0xa0
[ 3000.576533]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
[ 3000.576556] INFO: task btrfs-transacti:6770 blocked for more than
120 seconds.
[ 3000.576558] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3000.576559] btrfs-transacti D ffff8800a6d6f0c0     0  6770      2 0x00000000
[ 3000.576562]  ffff8801500f5dd8 0000000000000046 ffff8801500f5d18
ffff8801500f5fd8
[ 3000.576566]  ffff8801500f5fd8 0000000000004000 ffff88017f08dbc0
ffff88015eeb2de0
[ 3000.576569]  ffff8801a86c0000 ffff8801a86b3990 0000000000000000
0000000000000000
[ 3000.576573] Call Trace:
[ 3000.576577]  [<ffffffff8124cd05>] ? btrfs_free_path+0x25/0x30
[ 3000.576580]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
[ 3000.576583]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
[ 3000.576587]  [<ffffffff8128b1ff>] ? btrfs_run_ordered_operations+0x20f/0x2c0
[ 3000.576590]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
[ 3000.576593]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
[ 3000.576596]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3000.576600]  [<ffffffff81272d7d>] btrfs_commit_transaction+0x33d/0x960
[ 3000.576603]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
[ 3000.576607]  [<ffffffff8126ae3d>] transaction_kthread+0x19d/0x220
[ 3000.576610]  [<ffffffff8126aca0>] ? btrfs_alloc_root+0x30/0x30
[ 3000.576613]  [<ffffffff8105f7fb>] kthread+0xbb/0xc0
[ 3000.576617]  [<ffffffff81560000>] ? __schedule+0x4c0/0xa10
[ 3000.576620]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
[ 3000.576623]  [<ffffffff81567aec>] ret_from_fork+0x7c/0xb0
[ 3000.576626]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
[ 3000.576652] INFO: task mythpreviewgen:12052 blocked for more than
120 seconds.
[ 3000.576654] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3000.576655] mythpreviewgen  D ffff88015f6e8670     0 12052  12051 0x00000004
[ 3000.576659]  ffff8801066adc08 0000000000000082 ffff8801066adb08
ffff8801066adfd8
[ 3000.576662]  ffff8801066adfd8 0000000000004000 ffff8801a6cf96f0
ffff88018080ade0
[ 3000.576665]  ffff8801a655d0c0 ffff8801a655d0c0 000000006d5f7675
0000000000000000
[ 3000.576669] Call Trace:
[ 3000.576676]  [<ffffffffa01f7d4a>] ? do_expire_wait+0x17a/0x190 [autofs4]
[ 3000.576680]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
[ 3000.576683]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
[ 3000.576686]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
[ 3000.576689]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3000.576692]  [<ffffffff81560943>] schedule_preempt_disabled+0x13/0x20
[ 3000.576695]  [<ffffffff8155f0ec>] __mutex_lock_slowpath+0x12c/0x210
[ 3000.576699]  [<ffffffff8155e23d>] mutex_lock+0x1d/0x40
[ 3000.576702]  [<ffffffff8113d6e8>] do_last+0x268/0xd20
[ 3000.576705]  [<ffffffff8113a773>] ? inode_permission+0x13/0x50
[ 3000.576708]  [<ffffffff8113accd>] ? link_path_walk+0x23d/0x8e0
[ 3000.576711]  [<ffffffff8113e25d>] path_openat+0xbd/0x6b0
[ 3000.576715]  [<ffffffff8113eb8e>] do_filp_open+0x3e/0xa0
[ 3000.576718]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
[ 3000.576722]  [<ffffffff8114b31b>] ? __alloc_fd+0xcb/0x120
[ 3000.576725]  [<ffffffff8112e6ac>] do_sys_open+0x13c/0x230
[ 3000.576729]  [<ffffffff8112e7bd>] SyS_open+0x1d/0x20
[ 3000.576731]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
[ 3000.576734] INFO: task mythpreviewgen:12054 blocked for more than
120 seconds.
[ 3000.576736] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3000.576737] mythpreviewgen  D ffff8801a86c06e0     0 12054  12053 0x00000004
[ 3000.576740]  ffff880121141b28 0000000000000086 ffff880121141aa8
ffff880121141fd8
[ 3000.576744]  ffff880121141fd8 0000000000004000 ffff8801a6cfade0
ffff88000a795bc0
[ 3000.576747]  ffff880121141b58 ffffffff8125c7c7 ffff880121141a68
ffffffff81561ca1
[ 3000.576751] Call Trace:
[ 3000.576755]  [<ffffffff8125c7c7>] ? reserve_metadata_bytes+0x177/0x880
[ 3000.576758]  [<ffffffff81561ca1>] ? _raw_read_unlock+0x11/0x40
[ 3000.576762]  [<ffffffff812a6f88>] ? btrfs_set_lock_blocking_rw+0xd8/0x110
[ 3000.576766]  [<ffffffff81251d6f>] ? btrfs_search_slot+0x3ef/0x900
[ 3000.576769]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
[ 3000.576772]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
[ 3000.576775]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3000.576779]  [<ffffffff81272017>] wait_current_trans.isra.34+0xb7/0x120
[ 3000.576782]  [<ffffffff8127388c>] ? start_transaction+0x11c/0x4b0
[ 3000.576785]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
[ 3000.576789]  [<ffffffff81273a56>] start_transaction+0x2e6/0x4b0
[ 3000.576792]  [<ffffffff81273f66>] btrfs_start_transaction+0x16/0x20
[ 3000.576795]  [<ffffffff81280d82>] btrfs_create+0x42/0x210
[ 3000.576799]  [<ffffffff81275f27>] ? btrfs_permission+0x37/0x70
[ 3000.576802]  [<ffffffff8113a83e>] vfs_create+0x8e/0xf0
[ 3000.576805]  [<ffffffff8113dd66>] do_last+0x8e6/0xd20
[ 3000.576808]  [<ffffffff8113a773>] ? inode_permission+0x13/0x50
[ 3000.576812]  [<ffffffff8113e25d>] path_openat+0xbd/0x6b0
[ 3000.576815]  [<ffffffff8113eb8e>] do_filp_open+0x3e/0xa0
[ 3000.576818]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
[ 3000.576821]  [<ffffffff8114b31b>] ? __alloc_fd+0xcb/0x120
[ 3000.576825]  [<ffffffff8112e6ac>] do_sys_open+0x13c/0x230
[ 3000.576828]  [<ffffffff8112e7bd>] SyS_open+0x1d/0x20
[ 3000.576831]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
[ 3120.576415] INFO: task TFWWrite:11329 blocked for more than 120 seconds.
[ 3120.576419] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3120.576421] TFWWrite        D ffff8800a7ab5ac0     0 11329      1 0x00000000
[ 3120.576426]  ffff8800a7ab5a18 0000000000000082 0000000000000002
ffff8800a7ab5fd8
[ 3120.576431]  ffff8800a7ab5fd8 0000000000004000 ffff8801a6cfade0
ffff880099782de0
[ 3120.576434]  0000000000000000 00000000000000d3 00000000000001a6
0000000000000001
[ 3120.576438] Call Trace:
[ 3120.576447]  [<ffffffff81074bfe>] ? load_balance+0xfe/0x800
[ 3120.576451]  [<ffffffff8106e975>] ? sched_clock_local+0x25/0xa0
[ 3120.576455]  [<ffffffff810d89e0>] ? __lock_page+0x70/0x70
[ 3120.576460]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3120.576463]  [<ffffffff8156073a>] io_schedule+0x8a/0xd0
[ 3120.576466]  [<ffffffff810d89e9>] sleep_on_page+0x9/0x10
[ 3120.576469]  [<ffffffff8155e133>] __wait_on_bit_lock+0x53/0xb0
[ 3120.576473]  [<ffffffff810d89d2>] __lock_page+0x62/0x70
[ 3120.576477]  [<ffffffff810603c0>] ? wake_atomic_t_function+0x30/0x30
[ 3120.576480]  [<ffffffff810d8b71>] find_lock_page+0x51/0x80
[ 3120.576483]  [<ffffffff810d948a>] find_or_create_page+0x3a/0xc0
[ 3120.576487]  [<ffffffff8128443c>] prepare_pages.isra.23+0x18c/0x340
[ 3120.576491]  [<ffffffff81255990>] ? block_rsv_add_bytes+0x50/0x70
[ 3120.576495]  [<ffffffff81284fca>] __btrfs_buffered_write+0x29a/0x4e0
[ 3120.576499]  [<ffffffff81285425>] btrfs_file_aio_write+0x215/0x580
[ 3120.576502]  [<ffffffff8111b30e>] ? kmem_cache_free+0xae/0x180
[ 3120.576506]  [<ffffffff8113a4a1>] ? final_putname+0x21/0x50
[ 3120.576510]  [<ffffffff8112eb1b>] do_sync_write+0x7b/0xb0
[ 3120.576514]  [<ffffffff8112f8f0>] vfs_write+0xc0/0x1f0
[ 3120.576517]  [<ffffffff8112fded>] SyS_write+0x4d/0xa0
[ 3120.576521]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
[ 3120.576543] INFO: task btrfs-transacti:6770 blocked for more than
120 seconds.
[ 3120.576545] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3120.576546] btrfs-transacti D ffff8800a6d6f0c0     0  6770      2 0x00000000
[ 3120.576549]  ffff8801500f5dd8 0000000000000046 ffff8801500f5d18
ffff8801500f5fd8
[ 3120.576553]  ffff8801500f5fd8 0000000000004000 ffff88017f08dbc0
ffff88015eeb2de0
[ 3120.576556]  ffff8801a86c0000 ffff8801a86b3990 0000000000000000
0000000000000000
[ 3120.576560] Call Trace:
[ 3120.576563]  [<ffffffff8124cd05>] ? btrfs_free_path+0x25/0x30
[ 3120.576567]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
[ 3120.576570]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
[ 3120.576573]  [<ffffffff8128b1ff>] ? btrfs_run_ordered_operations+0x20f/0x2c0
[ 3120.576577]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
[ 3120.576580]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
[ 3120.576583]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3120.576587]  [<ffffffff81272d7d>] btrfs_commit_transaction+0x33d/0x960
[ 3120.576590]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
[ 3120.576594]  [<ffffffff8126ae3d>] transaction_kthread+0x19d/0x220
[ 3120.576597]  [<ffffffff8126aca0>] ? btrfs_alloc_root+0x30/0x30
[ 3120.576600]  [<ffffffff8105f7fb>] kthread+0xbb/0xc0
[ 3120.576604]  [<ffffffff81560000>] ? __schedule+0x4c0/0xa10
[ 3120.576607]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
[ 3120.576610]  [<ffffffff81567aec>] ret_from_fork+0x7c/0xb0
[ 3120.576613]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
[ 3120.576634] INFO: task kworker/u8:0:9957 blocked for more than 120 seconds.
[ 3120.576636] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3120.576637] kworker/u8:0    D ffff8801a4716d20     0  9957      2 0x00000000
[ 3120.576644] Workqueue: writeback bdi_writeback_workfn (flush-btrfs-7)
[ 3120.576646]  ffff88010080b6f8 0000000000000046 0000000000000000
ffff88010080bfd8
[ 3120.576649]  ffff88010080bfd8 0000000000004000 ffff8801758e16f0
ffff88014e4f2de0
[ 3120.576653]  ffff88010080b668 ffffffff8111b477 ffffffff810dadf0
0001120000000010
[ 3120.576656] Call Trace:
[ 3120.576659]  [<ffffffff8111b477>] ? kmem_cache_alloc+0x57/0xf0
[ 3120.576663]  [<ffffffff810dadf0>] ? mempool_alloc_slab+0x10/0x20
[ 3120.576666]  [<ffffffff810dadf0>] ? mempool_alloc_slab+0x10/0x20
[ 3120.576668]  [<ffffffff810db0f5>] ? mempool_alloc+0x55/0x150
[ 3120.576672]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
[ 3120.576675]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
[ 3120.576678]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3120.576682]  [<ffffffff81272017>] wait_current_trans.isra.34+0xb7/0x120
[ 3120.576685]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
[ 3120.576688]  [<ffffffff812739f8>] start_transaction+0x288/0x4b0
[ 3120.576692]  [<ffffffff81273ce2>] btrfs_join_transaction+0x12/0x20
[ 3120.576695]  [<ffffffff8127aa00>] cow_file_range+0x40/0xe0
[ 3120.576698]  [<ffffffff8127adfb>] run_delalloc_range+0x35b/0x390
[ 3120.576702]  [<ffffffff812907f9>] __extent_writepage+0x2b9/0x730
[ 3120.576706]  [<ffffffff8115c450>] ? end_buffer_async_read+0x1e0/0x1e0
[ 3120.576709]  [<ffffffff81162400>] ? I_BDEV+0x10/0x10
[ 3120.576713]  [<ffffffff813328c0>] ? merge+0x50/0xa0
[ 3120.576718]  [<ffffffff81290f02>]
extent_write_cache_pages.isra.40.constprop.57+0x292/0x3d0
[ 3120.576722]  [<ffffffff812912c8>] extent_writepages+0x48/0x60
[ 3120.576725]  [<ffffffff81276fd0>] ? btrfs_fiemap+0x60/0x60
[ 3120.576728]  [<ffffffff81275ee3>] btrfs_writepages+0x23/0x30
[ 3120.576732]  [<ffffffff810e2969>] do_writepages+0x19/0x40
[ 3120.576736]  [<ffffffff8115489e>] __writeback_single_inode+0x3e/0x140
[ 3120.576739]  [<ffffffff811559a6>] writeback_sb_inodes+0x276/0x3c0
[ 3120.576742]  [<ffffffff81155b87>] __writeback_inodes_wb+0x97/0xd0
[ 3120.576746]  [<ffffffff81155d8b>] wb_writeback+0x1cb/0x1e0
[ 3120.576749]  [<ffffffff811560ae>] bdi_writeback_workfn+0x15e/0x310
[ 3120.576754]  [<ffffffff810590d0>] process_one_work+0x140/0x390
[ 3120.576757]  [<ffffffff81059759>] worker_thread+0x119/0x370
[ 3120.576761]  [<ffffffff81059640>] ? rescuer_thread+0x2e0/0x2e0
[ 3120.576764]  [<ffffffff8105f7fb>] kthread+0xbb/0xc0
[ 3120.576767]  [<ffffffff81560000>] ? __schedule+0x4c0/0xa10
[ 3120.576771]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
[ 3120.576774]  [<ffffffff81567aec>] ret_from_fork+0x7c/0xb0
[ 3120.576777]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
[ 3120.576782] INFO: task mythpreviewgen:12052 blocked for more than
120 seconds.
[ 3120.576784] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3120.576785] mythpreviewgen  D ffff88015f6e8670     0 12052  12051 0x00000004
[ 3120.576789]  ffff8801066adc08 0000000000000082 ffff8801066adb08
ffff8801066adfd8
[ 3120.576792]  ffff8801066adfd8 0000000000004000 ffff8801a6cf96f0
ffff88018080ade0
[ 3120.576796]  ffff8801a655d0c0 ffff8801a655d0c0 000000006d5f7675
0000000000000000
[ 3120.576799] Call Trace:
[ 3120.576807]  [<ffffffffa01f7d4a>] ? do_expire_wait+0x17a/0x190 [autofs4]
[ 3120.576810]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
[ 3120.576813]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
[ 3120.576816]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
[ 3120.576819]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3120.576823]  [<ffffffff81560943>] schedule_preempt_disabled+0x13/0x20
[ 3120.576826]  [<ffffffff8155f0ec>] __mutex_lock_slowpath+0x12c/0x210
[ 3120.576829]  [<ffffffff8155e23d>] mutex_lock+0x1d/0x40
[ 3120.576832]  [<ffffffff8113d6e8>] do_last+0x268/0xd20
[ 3120.576835]  [<ffffffff8113a773>] ? inode_permission+0x13/0x50
[ 3120.576838]  [<ffffffff8113accd>] ? link_path_walk+0x23d/0x8e0
[ 3120.576841]  [<ffffffff8113e25d>] path_openat+0xbd/0x6b0
[ 3120.576845]  [<ffffffff8113eb8e>] do_filp_open+0x3e/0xa0
[ 3120.576848]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
[ 3120.576852]  [<ffffffff8114b31b>] ? __alloc_fd+0xcb/0x120
[ 3120.576855]  [<ffffffff8112e6ac>] do_sys_open+0x13c/0x230
[ 3120.576859]  [<ffffffff8112e7bd>] SyS_open+0x1d/0x20
[ 3120.576861]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
[ 3120.576864] INFO: task mythpreviewgen:12054 blocked for more than
120 seconds.
[ 3120.576866] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3120.576867] mythpreviewgen  D ffff8801a86c06e0     0 12054  12053 0x00000004
[ 3120.576870]  ffff880121141b28 0000000000000086 ffff880121141aa8
ffff880121141fd8
[ 3120.576874]  ffff880121141fd8 0000000000004000 ffff8801a6cfade0
ffff88000a795bc0
[ 3120.576877]  ffff880121141b58 ffffffff8125c7c7 ffff880121141a68
ffffffff81561ca1
[ 3120.576881] Call Trace:
[ 3120.576885]  [<ffffffff8125c7c7>] ? reserve_metadata_bytes+0x177/0x880
[ 3120.576888]  [<ffffffff81561ca1>] ? _raw_read_unlock+0x11/0x40
[ 3120.576892]  [<ffffffff812a6f88>] ? btrfs_set_lock_blocking_rw+0xd8/0x110
[ 3120.576895]  [<ffffffff81251d6f>] ? btrfs_search_slot+0x3ef/0x900
[ 3120.576899]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
[ 3120.576902]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
[ 3120.576905]  [<ffffffff81560664>] schedule+0x24/0x70
[ 3120.576908]  [<ffffffff81272017>] wait_current_trans.isra.34+0xb7/0x120
[ 3120.576911]  [<ffffffff8127388c>] ? start_transaction+0x11c/0x4b0
[ 3120.576915]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
[ 3120.576918]  [<ffffffff81273a56>] start_transaction+0x2e6/0x4b0
[ 3120.576922]  [<ffffffff81273f66>] btrfs_start_transaction+0x16/0x20
[ 3120.576925]  [<ffffffff81280d82>] btrfs_create+0x42/0x210
[ 3120.576928]  [<ffffffff81275f27>] ? btrfs_permission+0x37/0x70
[ 3120.576931]  [<ffffffff8113a83e>] vfs_create+0x8e/0xf0
[ 3120.576934]  [<ffffffff8113dd66>] do_last+0x8e6/0xd20
[ 3120.576937]  [<ffffffff8113a773>] ? inode_permission+0x13/0x50
[ 3120.576941]  [<ffffffff8113e25d>] path_openat+0xbd/0x6b0
[ 3120.576944]  [<ffffffff8113eb8e>] do_filp_open+0x3e/0xa0
[ 3120.576947]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
[ 3120.576951]  [<ffffffff8114b31b>] ? __alloc_fd+0xcb/0x120
[ 3120.576954]  [<ffffffff8112e6ac>] do_sys_open+0x13c/0x230
[ 3120.576957]  [<ffffffff8112e7bd>] SyS_open+0x1d/0x20
[ 3120.576960]  [<ffffffff81567b92>] system_call_fastpath+0x16/

-- 
John M. Drescher

Re: btrfs hung tasks

[Hugo Mills]

[-- Attachment #1: Type: text/plain, Size: 18873 bytes --]

[cc'd linux-btrfs]

On Sat, Oct 12, 2013 at 09:36:42AM -0400, John Drescher wrote:
> I am trying to debug this problem since it appears this is causing
> mythtv to truncate recordings on top of other very long delays.
> 
>  # uname -a
> Linux jmd0.comcast.net 3.11.4-gentoo-jmd0 #1 SMP PREEMPT Mon Oct 7
> 21:04:44 EDT 2013 x86_64 Intel(R) Core(TM)2 Quad CPU Q9550 @ 2.83GHz
> GenuineIntel GNU/Linux
> 
> Here is 1 example of a hung task:
> 
> [ 3000.576427] INFO: task TFWWrite:11329 blocked for more than 120 seconds.
> [ 3000.576430] "echo 0 > /proc/sys/kernel/hung_task_
> timeout_secs" disables this message.
> [ 3000.576433] TFWWrite        D ffff8800a7ab5ac0     0 11329      1 0x00000000
> [ 3000.576437]  ffff8800a7ab5a18 0000000000000082 0000000000000002
> ffff8800a7ab5fd8
> [ 3000.576442]  ffff8800a7ab5fd8 0000000000004000 ffff8801a6cfade0
> ffff880099782de0
> [ 3000.576445]  0000000000000000 00000000000000d3 00000000000001a6
> 0000000000000001
> [ 3000.576449] Call Trace:
> [ 3000.576458]  [<ffffffff81074bfe>] ? load_balance+0xfe/0x800
> [ 3000.576462]  [<ffffffff8106e975>] ? sched_clock_local+0x25/0xa0
> [ 3000.576466]  [<ffffffff810d89e0>] ? __lock_page+0x70/0x70
> [ 3000.576471]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3000.576474]  [<ffffffff8156073a>] io_schedule+0x8a/0xd0
> [ 3000.576477]  [<ffffffff810d89e9>] sleep_on_page+0x9/0x10
> [ 3000.576480]  [<ffffffff8155e133>] __wait_on_bit_lock+0x53/0xb0
> [ 3000.576484]  [<ffffffff810d89d2>] __lock_page+0x62/0x70
> [ 3000.576488]  [<ffffffff810603c0>] ? wake_atomic_t_function+0x30/0x30
> [ 3000.576492]  [<ffffffff810d8b71>] find_lock_page+0x51/0x80
> [ 3000.576495]  [<ffffffff810d948a>] find_or_create_page+0x3a/0xc0
> [ 3000.576499]  [<ffffffff8128443c>] prepare_pages.isra.23+0x18c/0x340
> [ 3000.576504]  [<ffffffff81255990>] ? block_rsv_add_bytes+0x50/0x70
> [ 3000.576508]  [<ffffffff81284fca>] __btrfs_buffered_write+0x29a/0x4e0
> [ 3000.576511]  [<ffffffff81285425>] btrfs_file_aio_write+0x215/0x580
> [ 3000.576515]  [<ffffffff8111b30e>] ? kmem_cache_free+0xae/0x180
> [ 3000.576519]  [<ffffffff8113a4a1>] ? final_putname+0x21/0x50
> [ 3000.576523]  [<ffffffff8112eb1b>] do_sync_write+0x7b/0xb0
> [ 3000.576527]  [<ffffffff8112f8f0>] vfs_write+0xc0/0x1f0
> [ 3000.576530]  [<ffffffff8112fded>] SyS_write+0x4d/0xa0
> [ 3000.576533]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
> [ 3000.576556] INFO: task btrfs-transacti:6770 blocked for more than
> 120 seconds.
> [ 3000.576558] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 3000.576559] btrfs-transacti D ffff8800a6d6f0c0     0  6770      2 0x00000000
> [ 3000.576562]  ffff8801500f5dd8 0000000000000046 ffff8801500f5d18
> ffff8801500f5fd8
> [ 3000.576566]  ffff8801500f5fd8 0000000000004000 ffff88017f08dbc0
> ffff88015eeb2de0
> [ 3000.576569]  ffff8801a86c0000 ffff8801a86b3990 0000000000000000
> 0000000000000000
> [ 3000.576573] Call Trace:
> [ 3000.576577]  [<ffffffff8124cd05>] ? btrfs_free_path+0x25/0x30
> [ 3000.576580]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
> [ 3000.576583]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
> [ 3000.576587]  [<ffffffff8128b1ff>] ? btrfs_run_ordered_operations+0x20f/0x2c0
> [ 3000.576590]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
> [ 3000.576593]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
> [ 3000.576596]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3000.576600]  [<ffffffff81272d7d>] btrfs_commit_transaction+0x33d/0x960
> [ 3000.576603]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
> [ 3000.576607]  [<ffffffff8126ae3d>] transaction_kthread+0x19d/0x220
> [ 3000.576610]  [<ffffffff8126aca0>] ? btrfs_alloc_root+0x30/0x30
> [ 3000.576613]  [<ffffffff8105f7fb>] kthread+0xbb/0xc0
> [ 3000.576617]  [<ffffffff81560000>] ? __schedule+0x4c0/0xa10
> [ 3000.576620]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
> [ 3000.576623]  [<ffffffff81567aec>] ret_from_fork+0x7c/0xb0
> [ 3000.576626]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
> [ 3000.576652] INFO: task mythpreviewgen:12052 blocked for more than
> 120 seconds.
> [ 3000.576654] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 3000.576655] mythpreviewgen  D ffff88015f6e8670     0 12052  12051 0x00000004
> [ 3000.576659]  ffff8801066adc08 0000000000000082 ffff8801066adb08
> ffff8801066adfd8
> [ 3000.576662]  ffff8801066adfd8 0000000000004000 ffff8801a6cf96f0
> ffff88018080ade0
> [ 3000.576665]  ffff8801a655d0c0 ffff8801a655d0c0 000000006d5f7675
> 0000000000000000
> [ 3000.576669] Call Trace:
> [ 3000.576676]  [<ffffffffa01f7d4a>] ? do_expire_wait+0x17a/0x190 [autofs4]
> [ 3000.576680]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
> [ 3000.576683]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
> [ 3000.576686]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
> [ 3000.576689]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3000.576692]  [<ffffffff81560943>] schedule_preempt_disabled+0x13/0x20
> [ 3000.576695]  [<ffffffff8155f0ec>] __mutex_lock_slowpath+0x12c/0x210
> [ 3000.576699]  [<ffffffff8155e23d>] mutex_lock+0x1d/0x40
> [ 3000.576702]  [<ffffffff8113d6e8>] do_last+0x268/0xd20
> [ 3000.576705]  [<ffffffff8113a773>] ? inode_permission+0x13/0x50
> [ 3000.576708]  [<ffffffff8113accd>] ? link_path_walk+0x23d/0x8e0
> [ 3000.576711]  [<ffffffff8113e25d>] path_openat+0xbd/0x6b0
> [ 3000.576715]  [<ffffffff8113eb8e>] do_filp_open+0x3e/0xa0
> [ 3000.576718]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
> [ 3000.576722]  [<ffffffff8114b31b>] ? __alloc_fd+0xcb/0x120
> [ 3000.576725]  [<ffffffff8112e6ac>] do_sys_open+0x13c/0x230
> [ 3000.576729]  [<ffffffff8112e7bd>] SyS_open+0x1d/0x20
> [ 3000.576731]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
> [ 3000.576734] INFO: task mythpreviewgen:12054 blocked for more than
> 120 seconds.
> [ 3000.576736] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 3000.576737] mythpreviewgen  D ffff8801a86c06e0     0 12054  12053 0x00000004
> [ 3000.576740]  ffff880121141b28 0000000000000086 ffff880121141aa8
> ffff880121141fd8
> [ 3000.576744]  ffff880121141fd8 0000000000004000 ffff8801a6cfade0
> ffff88000a795bc0
> [ 3000.576747]  ffff880121141b58 ffffffff8125c7c7 ffff880121141a68
> ffffffff81561ca1
> [ 3000.576751] Call Trace:
> [ 3000.576755]  [<ffffffff8125c7c7>] ? reserve_metadata_bytes+0x177/0x880
> [ 3000.576758]  [<ffffffff81561ca1>] ? _raw_read_unlock+0x11/0x40
> [ 3000.576762]  [<ffffffff812a6f88>] ? btrfs_set_lock_blocking_rw+0xd8/0x110
> [ 3000.576766]  [<ffffffff81251d6f>] ? btrfs_search_slot+0x3ef/0x900
> [ 3000.576769]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
> [ 3000.576772]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
> [ 3000.576775]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3000.576779]  [<ffffffff81272017>] wait_current_trans.isra.34+0xb7/0x120
> [ 3000.576782]  [<ffffffff8127388c>] ? start_transaction+0x11c/0x4b0
> [ 3000.576785]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
> [ 3000.576789]  [<ffffffff81273a56>] start_transaction+0x2e6/0x4b0
> [ 3000.576792]  [<ffffffff81273f66>] btrfs_start_transaction+0x16/0x20
> [ 3000.576795]  [<ffffffff81280d82>] btrfs_create+0x42/0x210
> [ 3000.576799]  [<ffffffff81275f27>] ? btrfs_permission+0x37/0x70
> [ 3000.576802]  [<ffffffff8113a83e>] vfs_create+0x8e/0xf0
> [ 3000.576805]  [<ffffffff8113dd66>] do_last+0x8e6/0xd20
> [ 3000.576808]  [<ffffffff8113a773>] ? inode_permission+0x13/0x50
> [ 3000.576812]  [<ffffffff8113e25d>] path_openat+0xbd/0x6b0
> [ 3000.576815]  [<ffffffff8113eb8e>] do_filp_open+0x3e/0xa0
> [ 3000.576818]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
> [ 3000.576821]  [<ffffffff8114b31b>] ? __alloc_fd+0xcb/0x120
> [ 3000.576825]  [<ffffffff8112e6ac>] do_sys_open+0x13c/0x230
> [ 3000.576828]  [<ffffffff8112e7bd>] SyS_open+0x1d/0x20
> [ 3000.576831]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
> [ 3120.576415] INFO: task TFWWrite:11329 blocked for more than 120 seconds.
> [ 3120.576419] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 3120.576421] TFWWrite        D ffff8800a7ab5ac0     0 11329      1 0x00000000
> [ 3120.576426]  ffff8800a7ab5a18 0000000000000082 0000000000000002
> ffff8800a7ab5fd8
> [ 3120.576431]  ffff8800a7ab5fd8 0000000000004000 ffff8801a6cfade0
> ffff880099782de0
> [ 3120.576434]  0000000000000000 00000000000000d3 00000000000001a6
> 0000000000000001
> [ 3120.576438] Call Trace:
> [ 3120.576447]  [<ffffffff81074bfe>] ? load_balance+0xfe/0x800
> [ 3120.576451]  [<ffffffff8106e975>] ? sched_clock_local+0x25/0xa0
> [ 3120.576455]  [<ffffffff810d89e0>] ? __lock_page+0x70/0x70
> [ 3120.576460]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3120.576463]  [<ffffffff8156073a>] io_schedule+0x8a/0xd0
> [ 3120.576466]  [<ffffffff810d89e9>] sleep_on_page+0x9/0x10
> [ 3120.576469]  [<ffffffff8155e133>] __wait_on_bit_lock+0x53/0xb0
> [ 3120.576473]  [<ffffffff810d89d2>] __lock_page+0x62/0x70
> [ 3120.576477]  [<ffffffff810603c0>] ? wake_atomic_t_function+0x30/0x30
> [ 3120.576480]  [<ffffffff810d8b71>] find_lock_page+0x51/0x80
> [ 3120.576483]  [<ffffffff810d948a>] find_or_create_page+0x3a/0xc0
> [ 3120.576487]  [<ffffffff8128443c>] prepare_pages.isra.23+0x18c/0x340
> [ 3120.576491]  [<ffffffff81255990>] ? block_rsv_add_bytes+0x50/0x70
> [ 3120.576495]  [<ffffffff81284fca>] __btrfs_buffered_write+0x29a/0x4e0
> [ 3120.576499]  [<ffffffff81285425>] btrfs_file_aio_write+0x215/0x580
> [ 3120.576502]  [<ffffffff8111b30e>] ? kmem_cache_free+0xae/0x180
> [ 3120.576506]  [<ffffffff8113a4a1>] ? final_putname+0x21/0x50
> [ 3120.576510]  [<ffffffff8112eb1b>] do_sync_write+0x7b/0xb0
> [ 3120.576514]  [<ffffffff8112f8f0>] vfs_write+0xc0/0x1f0
> [ 3120.576517]  [<ffffffff8112fded>] SyS_write+0x4d/0xa0
> [ 3120.576521]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
> [ 3120.576543] INFO: task btrfs-transacti:6770 blocked for more than
> 120 seconds.
> [ 3120.576545] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 3120.576546] btrfs-transacti D ffff8800a6d6f0c0     0  6770      2 0x00000000
> [ 3120.576549]  ffff8801500f5dd8 0000000000000046 ffff8801500f5d18
> ffff8801500f5fd8
> [ 3120.576553]  ffff8801500f5fd8 0000000000004000 ffff88017f08dbc0
> ffff88015eeb2de0
> [ 3120.576556]  ffff8801a86c0000 ffff8801a86b3990 0000000000000000
> 0000000000000000
> [ 3120.576560] Call Trace:
> [ 3120.576563]  [<ffffffff8124cd05>] ? btrfs_free_path+0x25/0x30
> [ 3120.576567]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
> [ 3120.576570]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
> [ 3120.576573]  [<ffffffff8128b1ff>] ? btrfs_run_ordered_operations+0x20f/0x2c0
> [ 3120.576577]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
> [ 3120.576580]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
> [ 3120.576583]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3120.576587]  [<ffffffff81272d7d>] btrfs_commit_transaction+0x33d/0x960
> [ 3120.576590]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
> [ 3120.576594]  [<ffffffff8126ae3d>] transaction_kthread+0x19d/0x220
> [ 3120.576597]  [<ffffffff8126aca0>] ? btrfs_alloc_root+0x30/0x30
> [ 3120.576600]  [<ffffffff8105f7fb>] kthread+0xbb/0xc0
> [ 3120.576604]  [<ffffffff81560000>] ? __schedule+0x4c0/0xa10
> [ 3120.576607]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
> [ 3120.576610]  [<ffffffff81567aec>] ret_from_fork+0x7c/0xb0
> [ 3120.576613]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
> [ 3120.576634] INFO: task kworker/u8:0:9957 blocked for more than 120 seconds.
> [ 3120.576636] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 3120.576637] kworker/u8:0    D ffff8801a4716d20     0  9957      2 0x00000000
> [ 3120.576644] Workqueue: writeback bdi_writeback_workfn (flush-btrfs-7)
> [ 3120.576646]  ffff88010080b6f8 0000000000000046 0000000000000000
> ffff88010080bfd8
> [ 3120.576649]  ffff88010080bfd8 0000000000004000 ffff8801758e16f0
> ffff88014e4f2de0
> [ 3120.576653]  ffff88010080b668 ffffffff8111b477 ffffffff810dadf0
> 0001120000000010
> [ 3120.576656] Call Trace:
> [ 3120.576659]  [<ffffffff8111b477>] ? kmem_cache_alloc+0x57/0xf0
> [ 3120.576663]  [<ffffffff810dadf0>] ? mempool_alloc_slab+0x10/0x20
> [ 3120.576666]  [<ffffffff810dadf0>] ? mempool_alloc_slab+0x10/0x20
> [ 3120.576668]  [<ffffffff810db0f5>] ? mempool_alloc+0x55/0x150
> [ 3120.576672]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
> [ 3120.576675]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
> [ 3120.576678]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3120.576682]  [<ffffffff81272017>] wait_current_trans.isra.34+0xb7/0x120
> [ 3120.576685]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
> [ 3120.576688]  [<ffffffff812739f8>] start_transaction+0x288/0x4b0
> [ 3120.576692]  [<ffffffff81273ce2>] btrfs_join_transaction+0x12/0x20
> [ 3120.576695]  [<ffffffff8127aa00>] cow_file_range+0x40/0xe0
> [ 3120.576698]  [<ffffffff8127adfb>] run_delalloc_range+0x35b/0x390
> [ 3120.576702]  [<ffffffff812907f9>] __extent_writepage+0x2b9/0x730
> [ 3120.576706]  [<ffffffff8115c450>] ? end_buffer_async_read+0x1e0/0x1e0
> [ 3120.576709]  [<ffffffff81162400>] ? I_BDEV+0x10/0x10
> [ 3120.576713]  [<ffffffff813328c0>] ? merge+0x50/0xa0
> [ 3120.576718]  [<ffffffff81290f02>]
> extent_write_cache_pages.isra.40.constprop.57+0x292/0x3d0
> [ 3120.576722]  [<ffffffff812912c8>] extent_writepages+0x48/0x60
> [ 3120.576725]  [<ffffffff81276fd0>] ? btrfs_fiemap+0x60/0x60
> [ 3120.576728]  [<ffffffff81275ee3>] btrfs_writepages+0x23/0x30
> [ 3120.576732]  [<ffffffff810e2969>] do_writepages+0x19/0x40
> [ 3120.576736]  [<ffffffff8115489e>] __writeback_single_inode+0x3e/0x140
> [ 3120.576739]  [<ffffffff811559a6>] writeback_sb_inodes+0x276/0x3c0
> [ 3120.576742]  [<ffffffff81155b87>] __writeback_inodes_wb+0x97/0xd0
> [ 3120.576746]  [<ffffffff81155d8b>] wb_writeback+0x1cb/0x1e0
> [ 3120.576749]  [<ffffffff811560ae>] bdi_writeback_workfn+0x15e/0x310
> [ 3120.576754]  [<ffffffff810590d0>] process_one_work+0x140/0x390
> [ 3120.576757]  [<ffffffff81059759>] worker_thread+0x119/0x370
> [ 3120.576761]  [<ffffffff81059640>] ? rescuer_thread+0x2e0/0x2e0
> [ 3120.576764]  [<ffffffff8105f7fb>] kthread+0xbb/0xc0
> [ 3120.576767]  [<ffffffff81560000>] ? __schedule+0x4c0/0xa10
> [ 3120.576771]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
> [ 3120.576774]  [<ffffffff81567aec>] ret_from_fork+0x7c/0xb0
> [ 3120.576777]  [<ffffffff8105f740>] ? kthread_freezable_should_stop+0x60/0x60
> [ 3120.576782] INFO: task mythpreviewgen:12052 blocked for more than
> 120 seconds.
> [ 3120.576784] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 3120.576785] mythpreviewgen  D ffff88015f6e8670     0 12052  12051 0x00000004
> [ 3120.576789]  ffff8801066adc08 0000000000000082 ffff8801066adb08
> ffff8801066adfd8
> [ 3120.576792]  ffff8801066adfd8 0000000000004000 ffff8801a6cf96f0
> ffff88018080ade0
> [ 3120.576796]  ffff8801a655d0c0 ffff8801a655d0c0 000000006d5f7675
> 0000000000000000
> [ 3120.576799] Call Trace:
> [ 3120.576807]  [<ffffffffa01f7d4a>] ? do_expire_wait+0x17a/0x190 [autofs4]
> [ 3120.576810]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
> [ 3120.576813]  [<ffffffff81561e26>] ? _raw_spin_lock+0x16/0x40
> [ 3120.576816]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
> [ 3120.576819]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3120.576823]  [<ffffffff81560943>] schedule_preempt_disabled+0x13/0x20
> [ 3120.576826]  [<ffffffff8155f0ec>] __mutex_lock_slowpath+0x12c/0x210
> [ 3120.576829]  [<ffffffff8155e23d>] mutex_lock+0x1d/0x40
> [ 3120.576832]  [<ffffffff8113d6e8>] do_last+0x268/0xd20
> [ 3120.576835]  [<ffffffff8113a773>] ? inode_permission+0x13/0x50
> [ 3120.576838]  [<ffffffff8113accd>] ? link_path_walk+0x23d/0x8e0
> [ 3120.576841]  [<ffffffff8113e25d>] path_openat+0xbd/0x6b0
> [ 3120.576845]  [<ffffffff8113eb8e>] do_filp_open+0x3e/0xa0
> [ 3120.576848]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
> [ 3120.576852]  [<ffffffff8114b31b>] ? __alloc_fd+0xcb/0x120
> [ 3120.576855]  [<ffffffff8112e6ac>] do_sys_open+0x13c/0x230
> [ 3120.576859]  [<ffffffff8112e7bd>] SyS_open+0x1d/0x20
> [ 3120.576861]  [<ffffffff81567b92>] system_call_fastpath+0x16/0x1b
> [ 3120.576864] INFO: task mythpreviewgen:12054 blocked for more than
> 120 seconds.
> [ 3120.576866] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 3120.576867] mythpreviewgen  D ffff8801a86c06e0     0 12054  12053 0x00000004
> [ 3120.576870]  ffff880121141b28 0000000000000086 ffff880121141aa8
> ffff880121141fd8
> [ 3120.576874]  ffff880121141fd8 0000000000004000 ffff8801a6cfade0
> ffff88000a795bc0
> [ 3120.576877]  ffff880121141b58 ffffffff8125c7c7 ffff880121141a68
> ffffffff81561ca1
> [ 3120.576881] Call Trace:
> [ 3120.576885]  [<ffffffff8125c7c7>] ? reserve_metadata_bytes+0x177/0x880
> [ 3120.576888]  [<ffffffff81561ca1>] ? _raw_read_unlock+0x11/0x40
> [ 3120.576892]  [<ffffffff812a6f88>] ? btrfs_set_lock_blocking_rw+0xd8/0x110
> [ 3120.576895]  [<ffffffff81251d6f>] ? btrfs_search_slot+0x3ef/0x900
> [ 3120.576899]  [<ffffffff81561e68>] ? _raw_spin_lock_irqsave+0x18/0x50
> [ 3120.576902]  [<ffffffff81561c23>] ? _raw_spin_unlock_irqrestore+0x13/0x40
> [ 3120.576905]  [<ffffffff81560664>] schedule+0x24/0x70
> [ 3120.576908]  [<ffffffff81272017>] wait_current_trans.isra.34+0xb7/0x120
> [ 3120.576911]  [<ffffffff8127388c>] ? start_transaction+0x11c/0x4b0
> [ 3120.576915]  [<ffffffff81060350>] ? abort_exclusive_wait+0xb0/0xb0
> [ 3120.576918]  [<ffffffff81273a56>] start_transaction+0x2e6/0x4b0
> [ 3120.576922]  [<ffffffff81273f66>] btrfs_start_transaction+0x16/0x20
> [ 3120.576925]  [<ffffffff81280d82>] btrfs_create+0x42/0x210
> [ 3120.576928]  [<ffffffff81275f27>] ? btrfs_permission+0x37/0x70
> [ 3120.576931]  [<ffffffff8113a83e>] vfs_create+0x8e/0xf0
> [ 3120.576934]  [<ffffffff8113dd66>] do_last+0x8e6/0xd20
> [ 3120.576937]  [<ffffffff8113a773>] ? inode_permission+0x13/0x50
> [ 3120.576941]  [<ffffffff8113e25d>] path_openat+0xbd/0x6b0
> [ 3120.576944]  [<ffffffff8113eb8e>] do_filp_open+0x3e/0xa0
> [ 3120.576947]  [<ffffffff81561be1>] ? _raw_spin_unlock+0x11/0x40
> [ 3120.576951]  [<ffffffff8114b31b>] ? __alloc_fd+0xcb/0x120
> [ 3120.576954]  [<ffffffff8112e6ac>] do_sys_open+0x13c/0x230
> [ 3120.576957]  [<ffffffff8112e7bd>] SyS_open+0x1d/0x20
> [ 3120.576960]  [<ffffffff81567b92>] system_call_fastpath+0x16/
> 

-- 
=== Hugo Mills: hugo@... carfax.org.uk | darksatanic.net | lug.org.uk ===
  PGP key: 65E74AC0 from wwwkeys.eu.pgp.net or http://www.carfax.org.uk
    --- Jazz is the sort of music where no-one plays anything the ---    
                             same way once.                              

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: btrfs hung tasks

[Josef Bacik]

On 07/29/2011 08:29 AM, Stephane Chazelas wrote:
> 2011-07-28 10:22:54 -0400, Josef Bacik:
>> On Thu, Jul 28, 2011 at 07:23:43AM +0100, Stephane Chazelas wrote:
>>> Hiya, I got below those last night. That was 3 minutes after a
>>> bunch of rsync and ntfsclone processes started.
>>>
>>> It's the first time it happens. I upgraded from 3.0rc6 to 3.0
>>> yesterday.
>>>
>>
>> Ok I fixed that recently and Chris just sent it to Linus.  The patch you are
>> looking for is
>>
>> Btrfs: use a worker thread to do caching
> [...]
>
> Thanks a lot Josef,
>
> That seems to have done the trick. I've not reproduced the issue
> yet with that patch applied. Strange that I only get the issue
> with 3.0 and not 3.0rc6  though....
>

Just bad luck really.  Thanks,

Josef

Re: btrfs hung tasks

[Stephane Chazelas]

2011-07-28 10:22:54 -0400, Josef Bacik:
> On Thu, Jul 28, 2011 at 07:23:43AM +0100, Stephane Chazelas wrote:
> > Hiya, I got below those last night. That was 3 minutes after a
> > bunch of rsync and ntfsclone processes started.
> > 
> > It's the first time it happens. I upgraded from 3.0rc6 to 3.0
> > yesterday.
> > 
> 
> Ok I fixed that recently and Chris just sent it to Linus.  The patch you are
> looking for is
> 
> Btrfs: use a worker thread to do caching
[...]

Thanks a lot Josef,

That seems to have done the trick. I've not reproduced the issue
yet with that patch applied. Strange that I only get the issue
with 3.0 and not 3.0rc6  though....

-- 
Stephane

Re: btrfs hung tasks

[Josef Bacik]

On Thu, Jul 28, 2011 at 07:23:43AM +0100, Stephane Chazelas wrote:
> Hiya, I got below those last night. That was 3 minutes after a
> bunch of rsync and ntfsclone processes started.
> 
> It's the first time it happens. I upgraded from 3.0rc6 to 3.0
> yesterday.
> 

Ok I fixed that recently and Chris just sent it to Linus.  The patch you are
looking for is

Btrfs: use a worker thread to do caching

Thanks,

Josef

Re: btrfs hung tasks

[Chris Samuel]

[-- Attachment #1: Type: Text/Plain, Size: 4074 bytes --]

On Thu, 28 Jul 2011 04:23:43 PM Stephane Chazelas wrote:

> Hiya, I got below those last night. That was 3 minutes after a
> bunch of rsync and ntfsclone processes started.

Similar here with an rsync to an external USB drive (SATA) from
a local ext4 partition.  This is with the Ubuntu mainline PPA
(AMD64) build of 3.0.

http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.0-oneiric/linux-image-3.0.0-0300-
generic_3.0.0-0300.201107220917_amd64.deb

[175681.180099] INFO: task flush-btrfs-1:26899 blocked for more than 120 seconds.
[175681.180104] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[175681.180106] flush-btrfs-1   D ffff88021e64df80     0 26899      2 0x00000000
[175681.180111]  ffff880152e597d0 0000000000000046 ffff880152e596d0 ffff880152e59fd8
[175681.180115]  ffff880152e597d0 0000000000012a40 0000000000012a40 ffff880152e59fd8
[175681.180119]  ffff880152e59fd8 0000000000012a40 ffff88021e64dbc0 ffff880222d28000
[175681.180124] Call Trace:
[175681.180132]  [<ffffffff812e90de>] ? radix_tree_gang_lookup_slot+0x7e/0xc0
[175681.180160]  [<ffffffffa0263394>] ? clear_extent_bit+0x194/0x380 [btrfs]
[175681.180166]  [<ffffffff8110e129>] ? find_get_pages_contig+0x39/0xe0
[175681.180171]  [<ffffffff81034f69>] ? default_spin_lock_flags+0x9/0x10
[175681.180175]  [<ffffffff815dfd84>] ? _raw_spin_lock_irqsave+0x34/0x50
[175681.180179]  [<ffffffff81084efc>] ? prepare_to_wait+0x7c/0x90
[175681.180192]  [<ffffffffa02430c9>] wait_current_trans+0x99/0x100 [btrfs]
[175681.180195]  [<ffffffff81084c40>] ? wake_up_bit+0x40/0x40
[175681.180198]  [<ffffffff815dfd3e>] ? _raw_spin_lock+0xe/0x20
[175681.180210]  [<ffffffffa0244ef8>] start_transaction+0x138/0x270 [btrfs]
[175681.180223]  [<ffffffffa0245085>] btrfs_join_transaction+0x15/0x20 [btrfs]
[175681.180236]  [<ffffffffa024a952>] cow_file_range+0x82/0x390 [btrfs]
[175681.180239]  [<ffffffff815dfd3e>] ? _raw_spin_lock+0xe/0x20
[175681.180252]  [<ffffffffa0264228>] ? test_range_bit+0x88/0x140 [btrfs]
[175681.180266]  [<ffffffffa024c6af>] run_delalloc_range+0x4f/0x80 [btrfs]
[175681.180279]  [<ffffffffa0266ac1>] __extent_writepage+0x4b1/0x650 [btrfs]
[175681.180283]  [<ffffffff812e9a40>] ? radix_tree_gang_lookup_tag_slot+0x90/0xd0
[175681.180287]  [<ffffffff8110d125>] ? find_get_pages_tag+0x45/0x100
[175681.180300]  [<ffffffffa0266138>] extent_write_cache_pages+0x208/0x2d0 [btrfs]
[175681.180314]  [<ffffffffa0262720>] ? flush_epd_write_bio+0x50/0x50 [btrfs]
[175681.180327]  [<ffffffffa0266610>] ? find_lock_delalloc_range+0x1d0/0x1d0 [btrfs]
[175681.180342]  [<ffffffffa0266254>] extent_writepages+0x54/0x70 [btrfs]
[175681.180355]  [<ffffffffa0250520>] ? btrfs_page_mkwrite+0x2d0/0x2d0 [btrfs]
[175681.180369]  [<ffffffffa0246f18>] btrfs_writepages+0x28/0x30 [btrfs]
[175681.180372]  [<ffffffff81117c51>] do_writepages+0x21/0x40
[175681.180376]  [<ffffffff81191514>] writeback_single_inode+0xf4/0x210
[175681.180380]  [<ffffffff8105844e>] ? put_prev_entity+0x2e/0x70
[175681.180383]  [<ffffffff811918e0>] writeback_sb_inodes+0xe0/0x190
[175681.180386]  [<ffffffff81191aff>] writeback_inodes_wb+0xcf/0xf0
[175681.180389]  [<ffffffff81191d63>] wb_writeback+0x243/0x370
[175681.180393]  [<ffffffff8107184b>] ? lock_timer_base+0x3b/0x70
[175681.180396]  [<ffffffff81191f19>] wb_check_old_data_flush+0x89/0xa0
[175681.180398]  [<ffffffff8119204b>] wb_do_writeback+0x8b/0xe0
[175681.180401]  [<ffffffff811920a0>] ? wb_do_writeback+0xe0/0xe0
[175681.180404]  [<ffffffff81192153>] bdi_writeback_thread+0xb3/0x260
[175681.180406]  [<ffffffff811920a0>] ? wb_do_writeback+0xe0/0xe0
[175681.180409]  [<ffffffff81084577>] kthread+0x97/0xa0
[175681.180413]  [<ffffffff815e94a4>] kernel_thread_helper+0x4/0x10
[175681.180416]  [<ffffffff810844e0>] ? kthread_bind+0x80/0x80
[175681.180419]  [<ffffffff815e94a0>] ? gs_change+0x13/0x13


-- 
 Chris Samuel  :  http://www.csamuel.org/  :  Melbourne, VIC

This email may come with a PGP signature as a file. Do not panic.
For more info see: http://en.wikipedia.org/wiki/OpenPGP

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 482 bytes --]

Re: btrfs hung tasks

[Stephane Chazelas]

2011-07-28 07:23:43 +0100, Stephane Chazelas:
> Hiya, I got below those last night. That was 3 minutes after a
> bunch of rsync and ntfsclone processes started.
> 
> It's the first time it happens. I upgraded from 3.0rc6 to 3.0
> yesterday.
[...]

And again this morning, though at that point only one ntfsclone
process was actively writing to the FS.

At this point, I can read directories and stat(2) files on that
FS, but reading or writing files hangs.

I'll try and revert to 3.0rc6 to see if that makes a difference.
call traces for some processes trying to read from the FS:

cat             D ffff8801424ee240     0  3478      1 0x00000005
 ffff8801424ee240 0000000000000086 ffff8801080497e8 ffff8800494322e0
 ffff8801461908b0 0000000000012800 ffff880108049fd8 ffff880108049fd8
 0000000000012800 ffff8801424ee240 0000000000012800 0000000000012800
Call Trace:
 [<ffffffff813367ec>] ? _raw_spin_lock_irqsave+0x9/0x25
 [<ffffffffa02d989c>] ? btrfs_tree_lock+0x9a/0xa7 [btrfs]
 [<ffffffffa02d9754>] ? btrfs_spin_on_block+0x49/0x49 [btrfs]
 [<ffffffffa0297edb>] ? btrfs_set_path_blocking+0x21/0x32 [btrfs]
 [<ffffffffa029ba81>] ? btrfs_search_slot+0x3c6/0x4d6 [btrfs]
 [<ffffffffa02a923a>] ? btrfs_lookup_csum+0x65/0x105 [btrfs]
 [<ffffffffa02c9bb2>] ? btrfs_lookup_ordered_extent+0x2b/0x69 [btrfs]
 [<ffffffffa02ca1fa>] ? btrfs_find_ordered_sum+0x34/0xcc [btrfs]
 [<ffffffffa02a9449>] ? __btrfs_lookup_bio_sums+0x16f/0x2ed [btrfs]
 [<ffffffffa02e3bb8>] ? btrfs_submit_compressed_read+0x3b7/0x42e [btrfs]
 [<ffffffffa02ca73b>] ? submit_one_bio+0x85/0xbc [btrfs]
 [<ffffffffa02cc880>] ? submit_extent_page.clone.16+0x118/0x1b9 [btrfs]
 [<ffffffffa02cc290>] ? check_page_uptodate+0x36/0x36 [btrfs]
 [<ffffffffa02ccda4>] ? __extent_read_full_page+0x463/0x4cc [btrfs]
 [<ffffffffa02cc290>] ? check_page_uptodate+0x36/0x36 [btrfs]
 [<ffffffffa02b4e09>] ? uncompress_inline.clone.32+0x117/0x117 [btrfs]
 [<ffffffffa02cd92b>] ? extent_readpages+0xb1/0xf6 [btrfs]
 [<ffffffffa02b4e09>] ? uncompress_inline.clone.32+0x117/0x117 [btrfs]
 [<ffffffff810be21b>] ? __do_page_cache_readahead+0x124/0x1c8
 [<ffffffff810be526>] ? ra_submit+0x1c/0x23
 [<ffffffff810b6e9e>] ? generic_file_aio_read+0x2a7/0x5c7
 [<ffffffff810fb5f1>] ? do_sync_read+0xb1/0xea
 [<ffffffff81336815>] ? _raw_spin_lock_irq+0xd/0x1a
 [<ffffffff810fbc10>] ? vfs_read+0x9f/0xf2
 [<ffffffff81012599>] ? syscall_trace_enter+0xb5/0x15d
 [<ffffffff810fbca8>] ? sys_read+0x45/0x6b
 [<ffffffff8133bca7>] ? tracesys+0xd9/0xde


wc              D ffff8801424ef710     0  3495      1 0x00000005
 ffff8801424ef710 0000000000000086 ffffffff811ab802 ffff88014951f5c0
 ffffffff8160b020 0000000000012800 ffff880109617fd8 ffff880109617fd8
 0000000000012800 ffff8801424ef710 0000000000012800 0000000000012800
Call Trace:
 [<ffffffff811ab802>] ? delay_tsc+0x2b/0x68
 [<ffffffff813367ec>] ? _raw_spin_lock_irqsave+0x9/0x25
 [<ffffffffa02d989c>] ? btrfs_tree_lock+0x9a/0xa7 [btrfs]
 [<ffffffffa02d9754>] ? btrfs_spin_on_block+0x49/0x49 [btrfs]
 [<ffffffffa02ce989>] ? map_private_extent_buffer+0xa3/0xc4 [btrfs]
 [<ffffffffa029816d>] ? btrfs_lock_root_node+0x1d/0x3f [btrfs]
 [<ffffffffa029b7a1>] ? btrfs_search_slot+0xe6/0x4d6 [btrfs]
 [<ffffffffa02ac5a1>] ? btrfs_header_generation.clone.17+0xf/0x14 [btrfs]
 [<ffffffffa02a923a>] ? btrfs_lookup_csum+0x65/0x105 [btrfs]
 [<ffffffffa02c9bb2>] ? btrfs_lookup_ordered_extent+0x2b/0x69 [btrfs]
 [<ffffffffa02ca1fa>] ? btrfs_find_ordered_sum+0x34/0xcc [btrfs]
 [<ffffffffa02a9449>] ? __btrfs_lookup_bio_sums+0x16f/0x2ed [btrfs]
 [<ffffffffa02b3226>] ? btrfs_submit_bio_hook+0xa4/0x129 [btrfs]
 [<ffffffffa02ca73b>] ? submit_one_bio+0x85/0xbc [btrfs]
 [<ffffffffa02cc880>] ? submit_extent_page.clone.16+0x118/0x1b9 [btrfs]
 [<ffffffffa02cc290>] ? check_page_uptodate+0x36/0x36 [btrfs]
 [<ffffffffa02ccda4>] ? __extent_read_full_page+0x463/0x4cc [btrfs]
 [<ffffffffa02cc290>] ? check_page_uptodate+0x36/0x36 [btrfs]
 [<ffffffffa02b4e09>] ? uncompress_inline.clone.32+0x117/0x117 [btrfs]
 [<ffffffffa02cd92b>] ? extent_readpages+0xb1/0xf6 [btrfs]
 [<ffffffffa02b4e09>] ? uncompress_inline.clone.32+0x117/0x117 [btrfs]
 [<ffffffff810be21b>] ? __do_page_cache_readahead+0x124/0x1c8
 [<ffffffff810be526>] ? ra_submit+0x1c/0x23
 [<ffffffff810b6e62>] ? generic_file_aio_read+0x26b/0x5c7
 [<ffffffff810fb5f1>] ? do_sync_read+0xb1/0xea
 [<ffffffff81336815>] ? _raw_spin_lock_irq+0xd/0x1a
 [<ffffffff810fbc10>] ? vfs_read+0x9f/0xf2
 [<ffffffff81012599>] ? syscall_trace_enter+0xb5/0x15d
 [<ffffffff810fbca8>] ? sys_read+0x45/0x6b
 [<ffffffff8133bca7>] ? tracesys+0xd9/0xde


tail            D ffff88014651b750     0  3442   1844 0x00000004
 ffff88014651b750 0000000000000082 ffff880147b06508 ffffffff00000000
 ffff8801495660c0 0000000000012800 ffff88010e05dfd8 ffff88010e05dfd8
 0000000000012800 ffff88014651b750 0000000000012800 0000000000012800
Call Trace:
 [<ffffffff81335e18>] ? __mutex_lock_common.clone.5+0x114/0x179
 [<ffffffff81335cf1>] ? mutex_lock+0x1a/0x2d
 [<ffffffff810fb6d8>] ? generic_file_llseek+0x21/0x52
 [<ffffffff810fb745>] ? sys_lseek+0x3c/0x59
 [<ffffffff8133ba92>] ? system_call_fastpath+0x16/0x1b


rm              D ffff8801424bd060     0  3504      1 0x00000005
 ffff8801424bd060 0000000000000086 0000000000000000 0000000000000001
 ffff8801495660c0 0000000000012800 ffff880118b21fd8 ffff880118b21fd8
 0000000000012800 ffff8801424bd060 0000000000012800 0000000000012800
Call Trace:
 [<ffffffff813367ec>] ? _raw_spin_lock_irqsave+0x9/0x25
 [<ffffffffa02b0b91>] ? wait_current_trans.clone.22+0xa1/0xd0 [btrfs]
 [<ffffffff81060083>] ? wake_up_bit+0x23/0x23
 [<ffffffffa02b1d3f>] ? start_transaction+0xd9/0x227 [btrfs]
 [<ffffffffa02b2a3d>] ? __unlink_start_trans+0x52/0x399 [btrfs]
 [<ffffffff8103840a>] ? should_resched+0x5/0x24
 [<ffffffff8133565f>] ? _cond_resched+0x9/0x20
 [<ffffffff811038d1>] ? generic_permission+0xe/0x9b
 [<ffffffffa02b898f>] ? btrfs_unlink+0x1e/0xa4 [btrfs]
 [<ffffffff81104706>] ? vfs_unlink+0x65/0xbe
 [<ffffffff811068e3>] ? do_unlinkat+0xc6/0x14d
 [<ffffffff81011968>] ? ptrace_report_syscall.clone.8+0x27/0x4f
 [<ffffffff81012599>] ? syscall_trace_enter+0xb5/0x15d
 [<ffffffff8133bca7>] ? tracesys+0xd9/0xde


tee             D ffff88013d9d4140     0  3506      1 0x00000005
 ffff88013d9d4140 0000000000000082 ffff880142634c40 ffff880142634730
 ffffffff8160b020 0000000000012800 ffff88007e18bfd8 ffff88007e18bfd8
 0000000000012800 ffff88013d9d4140 0000000000012800 0000000000012800
Call Trace:
 [<ffffffff8103b012>] ? perf_event_task_sched_out+0x48/0x54
 [<ffffffff81335e18>] ? __mutex_lock_common.clone.5+0x114/0x179
 [<ffffffff81103865>] ? exec_permission+0x1f/0x7d
 [<ffffffff81335cf1>] ? mutex_lock+0x1a/0x2d
 [<ffffffff8110558f>] ? do_last+0x19b/0x584
 [<ffffffff81106bea>] ? path_openat+0xc7/0x349
 [<ffffffff81336815>] ? _raw_spin_lock_irq+0xd/0x1a
 [<ffffffff81106e98>] ? do_filp_open+0x2c/0x72
 [<ffffffff8133565f>] ? _cond_resched+0x9/0x20
 [<ffffffff811ac741>] ? __strncpy_from_user+0x19/0x4a
 [<ffffffff81110208>] ? alloc_fd+0x69/0x110
 [<ffffffff810fb138>] ? do_sys_open+0x5f/0xe6
 [<ffffffff8133bca7>] ? tracesys+0xd9/0xde


ntfsclone       D ffff88013e4fd160     0  2757   2601 0x00000004
 ffff88013e4fd160 0000000000000082 ffff88013f390710 ffffffff81023145
 ffff8801495660c0 0000000000012800 ffff8801094f1fd8 ffff8801094f1fd8
 0000000000012800 ffff88013e4fd160 0000000000012800 0000000000012800
Call Trace:
 [<ffffffff81023145>] ? _flat_send_IPI_mask+0x6a/0x7c
 [<ffffffff8100e342>] ? read_tsc+0x5/0x14
 [<ffffffff81066feb>] ? timekeeping_get_ns+0xd/0x2a
 [<ffffffff810b5c70>] ? lock_page+0x20/0x20
 [<ffffffff813354f3>] ? io_schedule+0x5b/0x75
 [<ffffffff810b5c79>] ? sleep_on_page+0x9/0x10
 [<ffffffff81335b74>] ? __wait_on_bit+0x3e/0x71
 [<ffffffff8103840a>] ? should_resched+0x5/0x24
 [<ffffffff8133565f>] ? _cond_resched+0x9/0x20
 [<ffffffff810b5e11>] ? wait_on_page_bit+0x6a/0x70
 [<ffffffff810600ad>] ? autoremove_wake_function+0x2a/0x2a
 [<ffffffffa02bd29e>] ? prepare_pages.clone.12+0x15b/0x2fd [btrfs]
 [<ffffffffa02bda5a>] ? __btrfs_buffered_write.clone.14+0x132/0x29a [btrfs]
 [<ffffffff81117b72>] ? inode_to_bdi+0x20/0x42
 [<ffffffffa02bdf5d>] ? btrfs_file_aio_write+0x39b/0x435 [btrfs]
 [<ffffffff810fb507>] ? do_sync_write+0xb1/0xea
 [<ffffffff81126459>] ? fsnotify+0x23d/0x24f
 [<ffffffff811650d9>] ? security_file_permission+0x18/0x33
 [<ffffffff810fbb1e>] ? vfs_write+0xa6/0xf9
 [<ffffffff810fbd13>] ? sys_write+0x45/0x6b
 [<ffffffff8133ba92>] ? system_call_fastpath+0x16/0x1b


Best regards,
Stephane

btrfs hung tasks

[Stephane Chazelas]

[-- Attachment #1: Type: text/plain, Size: 20330 bytes --]

Hiya, I got below those last night. That was 3 minutes after a
bunch of rsync and ntfsclone processes started.

It's the first time it happens. I upgraded from 3.0rc6 to 3.0
yesterday.

sysrq-t output attached.

[30961.476020] INFO: task kthreadd:2 blocked for more than 120 seconds.
[30961.482414] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30961.490271] kthreadd        D ffff880149526e20     0     2      0 0x00000000
[30961.497489]  ffff880149526e20 0000000000000046 ffff88014fffb700 ffffea00007eb520
[30961.504977]  ffff880147045890 0000000000012800 ffff88014952ffd8 ffff88014952ffd8
[30961.512525]  0000000000012800 ffff880149526e20 0000000000012800 0000000000012800
[30961.520179] Call Trace:
[30961.522702]  [<ffffffff8100e342>] ? read_tsc+0x5/0x14
[30961.527850]  [<ffffffff81066feb>] ? timekeeping_get_ns+0xd/0x2a
[30961.533861]  [<ffffffff810b5c70>] ? lock_page+0x20/0x20
[30961.539134]  [<ffffffff813354f3>] ? io_schedule+0x5b/0x75
[30961.548853]  [<ffffffff810b5c79>] ? sleep_on_page+0x9/0x10
[30961.554424]  [<ffffffff81335b74>] ? __wait_on_bit+0x3e/0x71
[30961.560042]  [<ffffffff810b5e11>] ? wait_on_page_bit+0x6a/0x70
[30961.565912]  [<ffffffff810600ad>] ? autoremove_wake_function+0x2a/0x2a
[30961.572478]  [<ffffffff810ef92d>] ? migrate_pages+0x1b6/0x39b
[30961.578243]  [<ffffffff810e851b>] ? suitable_migration_target+0x35/0x35
[30961.584877]  [<ffffffff810e8ee2>] ? compact_zone+0x68e/0x6a1
[30961.590567]  [<ffffffff8110b5f1>] ? shrink_dcache_memory+0x132/0x15d
[30961.596934]  [<ffffffff810e9075>] ? compact_zone_order+0x9e/0xab
[30961.602954]  [<ffffffff810e9112>] ? try_to_compact_pages+0x90/0xe6
[30961.609147]  [<ffffffff810bc393>] ? __alloc_pages_direct_compact+0xac/0x163
[30961.616124]  [<ffffffff810bc8cf>] ? __alloc_pages_nodemask+0x485/0x75c
[30961.622665]  [<ffffffff81044a50>] ? copy_process+0x109/0x10eb
[30961.628462]  [<ffffffff8103b012>] ? perf_event_task_sched_out+0x48/0x54
[30961.635108]  [<ffffffff81045b60>] ? do_fork+0xff/0x263
[30961.640262]  [<ffffffff8100f1e0>] ? kernel_thread+0x7b/0x83
[30961.645846]  [<ffffffff8105fb91>] ? kthread_worker_fn+0x149/0x149
[30961.651955]  [<ffffffff8133cba0>] ? gs_change+0x13/0x13
[30961.657193]  [<ffffffff8105ff3e>] ? kthreadd+0xe7/0x125
[30961.662434]  [<ffffffff8103b0a2>] ? finish_task_switch+0x84/0xaf
[30961.668477]  [<ffffffff8133cba4>] ? kernel_thread_helper+0x4/0x10
[30961.674587]  [<ffffffff8105fe57>] ? tsk_fork_get_node+0x1a/0x1a
[30961.680518]  [<ffffffff8133cba0>] ? gs_change+0x13/0x13
[30961.685772] INFO: task btrfs-delayed-m:785 blocked for more than 120 seconds.
[30961.692919] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30961.700793] btrfs-delayed-m D ffff88014628a300     0   785      2 0x00000000
[30961.707874]  ffff88014628a300 0000000000000046 ffff88014549cc28 000000000000eb3f
[30961.715347]  ffff880147044ab0 0000000000012800 ffff8801484c3fd8 ffff8801484c3fd8
[30961.722816]  0000000000012800 ffff88014628a300 0000000000012800 0000000000012800
[30961.730283] Call Trace:
[30961.732750]  [<ffffffff813367ec>] ? _raw_spin_lock_irqsave+0x9/0x25
[30961.739056]  [<ffffffffa02bb89c>] ? btrfs_tree_lock+0x9a/0xa7 [btrfs]
[30961.745524]  [<ffffffffa02bb754>] ? btrfs_spin_on_block+0x49/0x49 [btrfs]
[30961.752337]  [<ffffffffa027a16d>] ? btrfs_lock_root_node+0x1d/0x3f [btrfs]
[30961.759231]  [<ffffffffa027d7a1>] ? btrfs_search_slot+0xe6/0x4d6 [btrfs]
[30961.765948]  [<ffffffff81335ce4>] ? mutex_lock+0xd/0x2d
[30961.771190]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30961.776809]  [<ffffffffa028c82a>] ? btrfs_lookup_inode+0x25/0x87 [btrfs]
[30961.783527]  [<ffffffff810383fc>] ? need_resched+0x1a/0x23
[30961.789062]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30961.794654]  [<ffffffff8133565f>] ? _cond_resched+0x9/0x20
[30961.800155]  [<ffffffff81335ce4>] ? mutex_lock+0xd/0x2d
[30961.805412]  [<ffffffffa02cd6c3>] ? btrfs_update_delayed_inode+0x6b/0x126 [btrfs]
[30961.812967]  [<ffffffffa02ce2a0>] ? btrfs_async_run_delayed_node_done+0x9f/0x1cb [btrfs]
[30961.821126]  [<ffffffffa02b6f8a>] ? worker_loop+0x17e/0x498 [btrfs]
[30961.827420]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30961.834320]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30961.841209]  [<ffffffff8105fc0b>] ? kthread+0x7a/0x82
[30961.846276]  [<ffffffff8133cba4>] ? kernel_thread_helper+0x4/0x10
[30961.852381]  [<ffffffff8105fb91>] ? kthread_worker_fn+0x149/0x149
[30961.858487]  [<ffffffff8133cba0>] ? gs_change+0x13/0x13
[30961.863725] INFO: task btrfs-transacti:892 blocked for more than 120 seconds.
[30961.870870] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30961.878727] btrfs-transacti D ffff880147e24ee0     0   892      2 0x00000000
[30961.885811]  ffff880147e24ee0 0000000000000046 ffffea000006f318 ffff880000000000
[30961.893280]  ffff8801495660c0 0000000000012800 ffff880144357fd8 ffff880144357fd8
[30961.900743]  0000000000012800 ffff880147e24ee0 0000000000012800 0000000000012800
[30961.908210] Call Trace:
[30961.910669]  [<ffffffff8100e342>] ? read_tsc+0x5/0x14
[30961.915737]  [<ffffffff810b5c70>] ? lock_page+0x20/0x20
[30961.920978]  [<ffffffff813354f3>] ? io_schedule+0x5b/0x75
[30961.926390]  [<ffffffff810b5c79>] ? sleep_on_page+0x9/0x10
[30961.931888]  [<ffffffff81335b74>] ? __wait_on_bit+0x3e/0x71
[30961.937473]  [<ffffffff810b5e11>] ? wait_on_page_bit+0x6a/0x70
[30961.943320]  [<ffffffff810600ad>] ? autoremove_wake_function+0x2a/0x2a
[30961.949871]  [<ffffffffa02ac5f5>] ? lock_page+0x11/0x20 [btrfs]
[30961.955817]  [<ffffffffa02af4e3>] ? extent_write_cache_pages.clone.10.clone.17+0xed/0x21f [btrfs]
[30961.964730]  [<ffffffff810be856>] ? pagevec_lookup_tag+0x18/0x1f
[30961.970757]  [<ffffffff810b6468>] ? filemap_fdatawait_range+0x12c/0x14a
[30961.977400]  [<ffffffffa02af864>] ? extent_writepages+0x44/0x5a [btrfs]
[30961.984042]  [<ffffffffa0296e09>] ? uncompress_inline.clone.32+0x117/0x117 [btrfs]
[30961.991639]  [<ffffffff810b6729>] ? __filemap_fdatawrite_range+0x4b/0x50
[30961.998365]  [<ffffffffa02abd38>] ? btrfs_wait_ordered_range+0x53/0x11e [btrfs]
[30962.005706]  [<ffffffff810383fc>] ? need_resched+0x1a/0x23
[30962.011202]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30962.016799]  [<ffffffffa02abf30>] ? btrfs_run_ordered_operations+0x12d/0x1b6 [btrfs]
[30962.024584]  [<ffffffffa029354b>] ? btrfs_commit_transaction+0x22e/0x6fd [btrfs]
[30962.032011]  [<ffffffff810ece49>] ? kmem_cache_alloc+0x86/0xf0
[30962.037867]  [<ffffffffa0292c7b>] ? join_transaction.clone.23+0xbb/0x1fc [btrfs]
[30962.045293]  [<ffffffff81060083>] ? wake_up_bit+0x23/0x23
[30962.050705]  [<ffffffff810383fc>] ? need_resched+0x1a/0x23
[30962.056202]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30962.061800]  [<ffffffffa028ddd7>] ? transaction_kthread+0x171/0x229 [btrfs]
[30962.068785]  [<ffffffffa028dc66>] ? btrfs_congested_fn+0x7b/0x7b [btrfs]
[30962.075508]  [<ffffffffa028dc66>] ? btrfs_congested_fn+0x7b/0x7b [btrfs]
[30962.082223]  [<ffffffff8105fc0b>] ? kthread+0x7a/0x82
[30962.087288]  [<ffffffff8133cba4>] ? kernel_thread_helper+0x4/0x10
[30962.093393]  [<ffffffff8105fb91>] ? kthread_worker_fn+0x149/0x149
[30962.099501]  [<ffffffff8133cba0>] ? gs_change+0x13/0x13
[30962.104755] INFO: task btrfs-delalloc-:2380 blocked for more than 120 seconds.
[30962.112007] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30962.119860] btrfs-delalloc- D ffff880143f9a340     0  2380      2 0x00000000
[30962.126941]  ffff880143f9a340 0000000000000046 ffff88014fffbe00 ffffffff00000000
[30962.134410]  ffffffff8160b020 0000000000012800 ffff880111f49fd8 ffff880111f49fd8
[30962.141876]  0000000000012800 ffff880143f9a340 0000000000012800 0000000000012800
[30962.149344] Call Trace:
[30962.151803]  [<ffffffff81335939>] ? schedule_timeout+0x2d/0xd7
[30962.157651]  [<ffffffff8100e28d>] ? paravirt_read_tsc+0x5/0x8
[30962.163411]  [<ffffffff8100e74a>] ? native_sched_clock+0x28/0x30
[30962.169430]  [<ffffffff8100e757>] ? sched_clock+0x5/0x8
[30962.174669]  [<ffffffff81335713>] ? wait_for_common+0x9d/0x116
[30962.180518]  [<ffffffff8103f0a4>] ? try_to_wake_up+0x199/0x199
[30962.186365]  [<ffffffff8105fdb6>] ? kthread_create_on_node+0x8f/0x10a
[30962.192825]  [<ffffffffa02827be>] ? btrfs_put_block_group+0x73/0x73 [btrfs]
[30962.199802]  [<ffffffff810eccd8>] ? __kmalloc+0xde/0xf0
[30962.205040]  [<ffffffff810383fc>] ? need_resched+0x1a/0x23
[30962.210555]  [<ffffffffa028271a>] ? cache_block_group+0x1f3/0x224 [btrfs]
[30962.217367]  [<ffffffffa028620b>] ? find_free_extent.clone.64+0x41a/0x932 [btrfs]
[30962.224890]  [<ffffffffa02b0a14>] ? map_extent_buffer+0x6a/0xa1 [btrfs]
[30962.231525]  [<ffffffffa0287006>] ? btrfs_reserve_extent+0xb0/0x18e [btrfs]
[30962.238512]  [<ffffffffa028767a>] ? btrfs_alloc_free_block+0x219/0x33f [btrfs]
[30962.245769]  [<ffffffffa027d24c>] ? split_leaf+0x2c6/0x523 [btrfs]
[30962.251969]  [<ffffffffa027dad6>] ? btrfs_search_slot+0x41b/0x4d6 [btrfs]
[30962.258777]  [<ffffffffa027ea43>] ? btrfs_insert_empty_items+0x62/0xb3 [btrfs]
[30962.266041]  [<ffffffffa0298da3>] ? insert_inline_extent+0xa5/0x231 [btrfs]
[30962.273029]  [<ffffffffa0299056>] ? cow_file_range_inline+0x127/0x166 [btrfs]
[30962.280189]  [<ffffffffa029a431>] ? compress_file_range+0x326/0x55a [btrfs]
[30962.287176]  [<ffffffffa029a693>] ? async_cow_start+0x2e/0x43 [btrfs]
[30962.293644]  [<ffffffffa02b6f8a>] ? worker_loop+0x17e/0x498 [btrfs]
[30962.299934]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30962.306831]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30962.313721]  [<ffffffff8105fc0b>] ? kthread+0x7a/0x82
[30962.318787]  [<ffffffff8133cba4>] ? kernel_thread_helper+0x4/0x10
[30962.324893]  [<ffffffff8105fb91>] ? kthread_worker_fn+0x149/0x149
[30962.330999]  [<ffffffff8133cba0>] ? gs_change+0x13/0x13
[30962.336256] INFO: task btrfs-endio-wri:2442 blocked for more than 120 seconds.
[30962.343504] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30962.351361] btrfs-endio-wri D ffff88013ee4d550     0  2442      2 0x00000000
[30962.358445]  ffff88013ee4d550 0000000000000046 ffff880028ef7b20 ffff880100e3ce20
[30962.365911]  ffff88003a95ea70 0000000000012800 ffff880028ef7fd8 ffff880028ef7fd8
[30962.373377]  0000000000012800 ffff88013ee4d550 0000000000012800 0000000000012800
[30962.380845] Call Trace:
[30962.383301]  [<ffffffff813367ec>] ? _raw_spin_lock_irqsave+0x9/0x25
[30962.389595]  [<ffffffffa02bb89c>] ? btrfs_tree_lock+0x9a/0xa7 [btrfs]
[30962.396063]  [<ffffffffa02bb754>] ? btrfs_spin_on_block+0x49/0x49 [btrfs]
[30962.402871]  [<ffffffffa0279edb>] ? btrfs_set_path_blocking+0x21/0x32 [btrfs]
[30962.410027]  [<ffffffffa027da81>] ? btrfs_search_slot+0x3c6/0x4d6 [btrfs]
[30962.416840]  [<ffffffffa028b5fb>] ? btrfs_lookup_file_extent+0x34/0x39 [btrfs]
[30962.424103]  [<ffffffffa02a03c1>] ? btrfs_drop_extents+0xe4/0x6eb [btrfs]
[30962.430904]  [<ffffffff810bd65d>] ? __set_page_dirty_nobuffers+0x16/0xd6
[30962.437619]  [<ffffffff810ed076>] ? kmem_cache_free+0x2d/0x69
[30962.443389]  [<ffffffffa0297beb>] ? insert_reserved_file_extent.clone.34+0x66/0x215 [btrfs]
[30962.451777]  [<ffffffffa0293e52>] ? start_transaction+0x1ec/0x227 [btrfs]
[30962.458585]  [<ffffffff810383fc>] ? need_resched+0x1a/0x23
[30962.464095]  [<ffffffffa0298a41>] ? btrfs_finish_ordered_io+0x1b6/0x298 [btrfs]
[30962.471433]  [<ffffffff810be064>] ? test_clear_page_writeback+0xb8/0xcc
[30962.478074]  [<ffffffffa02ad4dd>] ? end_bio_extent_writepage+0xa2/0x152 [btrfs]
[30962.489565]  [<ffffffffa02b6f8a>] ? worker_loop+0x17e/0x498 [btrfs]
[30962.495858]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30962.502755]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30962.509646]  [<ffffffff8105fc0b>] ? kthread+0x7a/0x82
[30962.514710]  [<ffffffff8133cba4>] ? kernel_thread_helper+0x4/0x10
[30962.520815]  [<ffffffff8105fb91>] ? kthread_worker_fn+0x149/0x149
[30962.526921]  [<ffffffff8133cba0>] ? gs_change+0x13/0x13
[30962.532177] INFO: task rsync:3139 blocked for more than 120 seconds.
[30962.538543] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30962.546402] rsync           D ffff88013bb86040     0  3139   3040 0x00000000
[30962.553485]  ffff88013bb86040 0000000000000082 0000000000000000 ffffffff00000000
[30962.560951]  ffffffff8160b020 0000000000012800 ffff88010d093fd8 ffff88010d093fd8
[30962.568416]  0000000000012800 ffff88013bb86040 0000000000012800 0000000000012800
[30962.575876] Call Trace:
[30962.578357]  [<ffffffffa0292b91>] ? wait_current_trans.clone.22+0xa1/0xd0 [btrfs]
[30962.585870]  [<ffffffff81060083>] ? wake_up_bit+0x23/0x23
[30962.591292]  [<ffffffffa0293d3f>] ? start_transaction+0xd9/0x227 [btrfs]
[30962.598010]  [<ffffffff810ed076>] ? kmem_cache_free+0x2d/0x69
[30962.603782]  [<ffffffffa029dbb1>] ? btrfs_create+0x33/0x18d [btrfs]
[30962.610062]  [<ffffffff810eccd8>] ? __kmalloc+0xde/0xf0
[30962.615304]  [<ffffffff811038d1>] ? generic_permission+0xe/0x9b
[30962.621234]  [<ffffffff811053d2>] ? vfs_create+0x66/0x88
[30962.626558]  [<ffffffff81103bf2>] ? d_alloc_and_lookup+0x3a/0x60
[30962.632577]  [<ffffffff81105636>] ? do_last+0x242/0x584
[30962.637814]  [<ffffffff81106bea>] ? path_openat+0xc7/0x349
[30962.643313]  [<ffffffff810fb5f1>] ? do_sync_read+0xb1/0xea
[30962.648816]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30962.654400]  [<ffffffff81106e98>] ? do_filp_open+0x2c/0x72
[30962.659898]  [<ffffffff8133565f>] ? _cond_resched+0x9/0x20
[30962.665402]  [<ffffffff811ac741>] ? __strncpy_from_user+0x19/0x4a
[30962.671509]  [<ffffffff81110208>] ? alloc_fd+0x69/0x110
[30962.676746]  [<ffffffff810fb138>] ? do_sys_open+0x5f/0xe6
[30962.682160]  [<ffffffff8133ba92>] ? system_call_fastpath+0x16/0x1b
[30962.688355] INFO: task btrfs-delayed-m:3321 blocked for more than 120 seconds.
[30962.695602] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30962.703459] btrfs-delayed-m D ffff880147044ab0     0  3321      2 0x00000000
[30962.710549]  ffff880147044ab0 0000000000000046 ffff88014549cc28 000000000000eb3f
[30962.718016]  ffff880143e6e340 0000000000012800 ffff88006c569fd8 ffff88006c569fd8
[30962.725482]  0000000000012800 ffff880147044ab0 0000000000012800 0000000000012800
[30962.732948] Call Trace:
[30962.735405]  [<ffffffff813367ec>] ? _raw_spin_lock_irqsave+0x9/0x25
[30962.741698]  [<ffffffffa02bb89c>] ? btrfs_tree_lock+0x9a/0xa7 [btrfs]
[30962.748167]  [<ffffffffa02bb754>] ? btrfs_spin_on_block+0x49/0x49 [btrfs]
[30962.754973]  [<ffffffffa027a16d>] ? btrfs_lock_root_node+0x1d/0x3f [btrfs]
[30962.761869]  [<ffffffffa027d7a1>] ? btrfs_search_slot+0xe6/0x4d6 [btrfs]
[30962.768584]  [<ffffffff81335ce4>] ? mutex_lock+0xd/0x2d
[30962.773822]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30962.779418]  [<ffffffffa028c82a>] ? btrfs_lookup_inode+0x25/0x87 [btrfs]
[30962.786133]  [<ffffffff810383fc>] ? need_resched+0x1a/0x23
[30962.791631]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30962.797215]  [<ffffffff8133565f>] ? _cond_resched+0x9/0x20
[30962.802716]  [<ffffffff81335ce4>] ? mutex_lock+0xd/0x2d
[30962.807965]  [<ffffffffa02cd6c3>] ? btrfs_update_delayed_inode+0x6b/0x126 [btrfs]
[30962.815485]  [<ffffffffa02ce2a0>] ? btrfs_async_run_delayed_node_done+0x9f/0x1cb [btrfs]
[30962.823616]  [<ffffffffa02b6f8a>] ? worker_loop+0x17e/0x498 [btrfs]
[30962.829907]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30962.836807]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30962.843694]  [<ffffffff8105fc0b>] ? kthread+0x7a/0x82
[30962.848760]  [<ffffffff8133cba4>] ? kernel_thread_helper+0x4/0x10
[30962.854868]  [<ffffffff8105fb91>] ? kthread_worker_fn+0x149/0x149
[30962.860972]  [<ffffffff8133cba0>] ? gs_change+0x13/0x13
[30962.866210] INFO: task ntfsclone:3437 blocked for more than 120 seconds.
[30962.872923] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30962.880777] ntfsclone       D ffff8800b26250a0     0  3437   3399 0x00000000
[30962.887856]  ffff8800b26250a0 0000000000000086 0000000000000296 ffffffff00000001
[30962.895323]  ffff8801428e6ee0 0000000000012800 ffff88003d6a3fd8 ffff88003d6a3fd8
[30962.902789]  0000000000012800 ffff8800b26250a0 0000000000012800 0000000000012800
[30962.910256] Call Trace:
[30962.912730]  [<ffffffffa0292b91>] ? wait_current_trans.clone.22+0xa1/0xd0 [btrfs]
[30962.920243]  [<ffffffff81060083>] ? wake_up_bit+0x23/0x23
[30962.925668]  [<ffffffffa029fb73>] ? __btrfs_buffered_write.clone.14+0x24b/0x29a [btrfs]
[30962.933711]  [<ffffffffa029ff5d>] ? btrfs_file_aio_write+0x39b/0x435 [btrfs]
[30962.940775]  [<ffffffff810fb507>] ? do_sync_write+0xb1/0xea
[30962.946363]  [<ffffffff811650d9>] ? security_file_permission+0x18/0x33
[30962.952907]  [<ffffffff810fbb1e>] ? vfs_write+0xa6/0xf9
[30962.958147]  [<ffffffff810fbd13>] ? sys_write+0x45/0x6b
[30962.963384]  [<ffffffff8133ba92>] ? system_call_fastpath+0x16/0x1b
[30962.969577] INFO: task btrfs-delayed-m:3438 blocked for more than 120 seconds.
[30962.976828] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30962.984684] btrfs-delayed-m D ffff8801428e6ee0     0  3438      2 0x00000000
[30962.991762]  ffff8801428e6ee0 0000000000000046 ffff8800299ebcf0 ffff88010df02c70
[30962.999229]  ffff880101862ab0 0000000000012800 ffff8800299ebfd8 ffff8800299ebfd8
[30963.006695]  0000000000012800 ffff8801428e6ee0 0000000000012800 0000000000012800
[30963.014163] Call Trace:
[30963.016625]  [<ffffffff813367ec>] ? _raw_spin_lock_irqsave+0x9/0x25
[30963.022917]  [<ffffffffa02bb89c>] ? btrfs_tree_lock+0x9a/0xa7 [btrfs]
[30963.029384]  [<ffffffffa02bb754>] ? btrfs_spin_on_block+0x49/0x49 [btrfs]
[30963.036193]  [<ffffffffa0279edb>] ? btrfs_set_path_blocking+0x21/0x32 [btrfs]
[30963.043346]  [<ffffffffa027da81>] ? btrfs_search_slot+0x3c6/0x4d6 [btrfs]
[30963.050150]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30963.055746]  [<ffffffffa028c82a>] ? btrfs_lookup_inode+0x25/0x87 [btrfs]
[30963.062460]  [<ffffffff810383fc>] ? need_resched+0x1a/0x23
[30963.067961]  [<ffffffff8103840a>] ? should_resched+0x5/0x24
[30963.073547]  [<ffffffff8133565f>] ? _cond_resched+0x9/0x20
[30963.079045]  [<ffffffff81335ce4>] ? mutex_lock+0xd/0x2d
[30963.084296]  [<ffffffffa02cd6c3>] ? btrfs_update_delayed_inode+0x6b/0x126 [btrfs]
[30963.091818]  [<ffffffffa02ce2a0>] ? btrfs_async_run_delayed_node_done+0x9f/0x1cb [btrfs]
[30963.099947]  [<ffffffffa02b6f8a>] ? worker_loop+0x17e/0x498 [btrfs]
[30963.106239]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30963.113138]  [<ffffffffa02b6e0c>] ? btrfs_queue_worker+0x25c/0x25c [btrfs]
[30963.120028]  [<ffffffff8105fc0b>] ? kthread+0x7a/0x82
[30963.125093]  [<ffffffff8133cba4>] ? kernel_thread_helper+0x4/0x10
[30963.131199]  [<ffffffff8105fb91>] ? kthread_worker_fn+0x149/0x149
[30963.137308]  [<ffffffff8133cba0>] ? gs_change+0x13/0x13
[30963.142544] INFO: task rsync:3439 blocked for more than 120 seconds.
[30963.148908] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[30963.156765] rsync           D ffff880114e02870     0  3439   3172 0x00000000
[30963.163843]  ffff880114e02870 0000000000000082 00000000000c0fff ffff880114e02ef8
[30963.171307]  ffff880146786040 0000000000012800 ffff8800d335bfd8 ffff8800d335bfd8
[30963.178775]  0000000000012800 ffff880114e02870 0000000000012800 0000000000012800
[30963.186240] Call Trace:
[30963.188704]  [<ffffffff813367ec>] ? _raw_spin_lock_irqsave+0x9/0x25
[30963.194994]  [<ffffffffa0292b91>] ? wait_current_trans.clone.22+0xa1/0xd0 [btrfs]
[30963.202511]  [<ffffffff81060083>] ? wake_up_bit+0x23/0x23
[30963.207936]  [<ffffffffa029fb73>] ? __btrfs_buffered_write.clone.14+0x24b/0x29a [btrfs]
[30963.215979]  [<ffffffffa029ff5d>] ? btrfs_file_aio_write+0x39b/0x435 [btrfs]
[30963.223043]  [<ffffffff811035df>] ? dget+0x12/0x1e
[30963.227846]  [<ffffffff8110ba59>] ? dput+0x29/0xea
[30963.232651]  [<ffffffff81111b05>] ? mntput_no_expire+0x21/0xd5
[30963.238499]  [<ffffffff810fb507>] ? do_sync_write+0xb1/0xea
[30963.244084]  [<ffffffff811650d9>] ? security_file_permission+0x18/0x33
[30963.250621]  [<ffffffff810fbb1e>] ? vfs_write+0xa6/0xf9
[30963.255860]  [<ffffffff810fbd13>] ? sys_write+0x45/0x6b
[30963.261097]  [<ffffffff8133ba92>] ? system_call_fastpath+0x16/0x1b

-- 
Stephane

[-- Attachment #2: sysrq-t.txt.xz --]
[-- Type: application/octet-stream, Size: 18152 bytes --]