Ceph » Linux kernel client

Wanting to accellerate CephFS access I added fscache. This resulted in a CephFS hang to the point that processes accessing /sys/kernel/debug/ceph/.. would also block. The CephFS hang occurred during the following:

- rebuild a linux kernel (on CentOS) using the src.rpm on CephFS (I symlinked ~/rpmbuild to a directory on CephFS)
- start a find from another session to find out what's happening.

Possibly the usage of fscache complicates thing in the current stage of the CephFS development cycle, so this may be considered for informational purposes only.

The kernel is based on the elrepo repository, it includes a patch provided in Bug #6914.

The dmesg results of the hang:

INFO: task kworker/0:1:2236 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:1 D ffffffff81814e20 0 2236 2 0x00000080
Workqueue: ceph-msgr con_work [libceph]
ffff88003aafba58 0000000000000046 ffff88003aafbfd8 0000000000014480
ffff88003aafa010 0000000000014480 0000000000014480 0000000000014480
ffff88003aafbfd8 0000000000014480 ffff88003c2fd080 ffffffff81c13480
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffff811c77da>] __wait_on_freeing_inode+0x9a/0xc0
[<ffffffff8108c240>] ? wake_atomic_t_function+0x40/0x40
[<ffffffffa02a5844>] ? fill_inode+0x5e4/0x7a0 [ceph]
[<ffffffffa02a32a0>] ? ceph_mount+0x1e0/0x1e0 [ceph]
[<ffffffff811c7950>] find_inode+0xa0/0xd0
[<ffffffffa02a32a0>] ? ceph_mount+0x1e0/0x1e0 [ceph]
[<ffffffff811c989f>] iget5_locked+0x5f/0x1c0
[<ffffffffa02a32d0>] ? ceph_ino_compare+0x30/0x30 [ceph]
[<ffffffffa02a4dcc>] ceph_get_inode+0x2c/0x70 [ceph]
[<ffffffffa02a7292>] ? ceph_init_dentry+0xc2/0xf0 [ceph]
[<ffffffffa02a646a>] ceph_readdir_prepopulate+0x42a/0x520 [ceph]
[<ffffffffa02ba8f2>] handle_reply+0x3f2/0x530 [ceph]
[<ffffffffa02bbbf3>] dispatch+0xe3/0x190 [ceph]
[<ffffffffa02710ab>] process_message+0xab/0xd0 [libceph]
[<ffffffffa0274212>] try_read+0x2d2/0x430 [libceph]
[<ffffffffa0274700>] con_work+0xc0/0x230 [libceph]
[<ffffffff8108458c>] process_one_work+0x17c/0x420
[<ffffffff810859f3>] worker_thread+0x123/0x400
[<ffffffff810858d0>] ? manage_workers+0x170/0x170
[<ffffffff8108b96e>] kthread+0xce/0xe0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
[<ffffffff8160fbfc>] ret_from_fork+0x7c/0xb0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
INFO: task grep:6376 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
grep D ffffffff81814e20 0 6376 6371 0x00000080
ffff88003ad95998 0000000000000082 ffff88003ad95fd8 0000000000014480
ffff88003ad94010 0000000000014480 0000000000014480 0000000000014480
ffff88003ad95fd8 0000000000014480 ffff880037079140 ffffffff81c13480
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffffa01a3b55>] __fscache_wait_on_page_write+0x75/0xb0 [fscache]
[<ffffffff8108c1c0>] ? wake_up_bit+0x40/0x40
[<ffffffff811a5175>] ? __mem_cgroup_uncharge_common+0xd5/0x2d0
[<ffffffffa02bda8a>] ceph_invalidate_fscache_page+0x2a/0x50 [ceph]
[<ffffffffa02aac6f>] ceph_invalidatepage+0x5f/0xc0 [ceph]
[<ffffffff8114f0a5>] do_invalidatepage+0x25/0x30
[<ffffffff8114f34f>] truncate_inode_page+0x8f/0xa0
[<ffffffff8114fa37>] truncate_inode_pages_range+0x1a7/0x630
[<ffffffff811d6c69>] ? __inode_wait_for_writeback+0x69/0xc0
[<ffffffff8108c240>] ? wake_atomic_t_function+0x40/0x40
[<ffffffff8114ff45>] truncate_inode_pages+0x15/0x20
[<ffffffff811c880e>] evict+0x1ae/0x1d0
[<ffffffff811c891f>] iput_final+0xef/0x190
[<ffffffff811c89fe>] iput+0x3e/0x50
[<ffffffff811c58c8>] dentry_kill+0x1b8/0x200
[<ffffffff811c5ce4>] dput+0x64/0x100
[<ffffffff811bbc08>] lookup_fast+0x298/0x2b0
[<ffffffff811bc215>] path_lookupat+0x105/0x750
[<ffffffff8116d466>] ? handle_pte_fault+0xe6/0x210
[<ffffffff8105bff7>] ? pte_alloc_one+0x37/0x50
[<ffffffff811bc894>] filename_lookup+0x34/0xc0
[<ffffffff811bdbd9>] user_path_at_empty+0x59/0xa0
[<ffffffff8160b090>] ? __do_page_fault+0x280/0x4f0
[<ffffffff811bdc31>] user_path_at+0x11/0x20
[<ffffffff811b3529>] vfs_fstatat+0x59/0xb0
[<ffffffff811b367b>] vfs_stat+0x1b/0x20
[<ffffffff811b369f>] SYSC_newstat+0x1f/0x50
[<ffffffff8160b30e>] ? do_page_fault+0xe/0x10
[<ffffffff816077d8>] ? page_fault+0x28/0x30
[<ffffffff811b36de>] SyS_newstat+0xe/0x10
[<ffffffff8160fca9>] system_call_fastpath+0x16/0x1b
INFO: task kworker/0:0:6382 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:0 D 0000000000000000 0 6382 2 0x00000080
Workqueue: events delayed_work [ceph]
ffff880037653bd8 0000000000000046 ffff880037653fd8 0000000000014480
ffff880037652010 0000000000014480 0000000000014480 0000000000014480
ffff880037653fd8 0000000000014480 ffff88003c33e8c0 ffff8800000942c0
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffff816056ce>] schedule_preempt_disabled+0xe/0x10
[<ffffffff81603f70>] __mutex_lock_slowpath+0x1a0/0x240
[<ffffffffa02ae385>] ? ceph_cap_string+0xe5/0x100 [ceph]
[<ffffffff81604033>] mutex_lock+0x23/0x40
[<ffffffffa02b145d>] ceph_check_caps+0x38d/0x780 [ceph]
[<ffffffffa02b19df>] ceph_check_delayed_caps+0x7f/0xb0 [ceph]
[<ffffffffa02b81dc>] delayed_work+0x2c/0x1e0 [ceph]
[<ffffffff8108458c>] process_one_work+0x17c/0x420
[<ffffffff810859f3>] worker_thread+0x123/0x400
[<ffffffff810858d0>] ? manage_workers+0x170/0x170
[<ffffffff8108b96e>] kthread+0xce/0xe0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
[<ffffffff8160fbfc>] ret_from_fork+0x7c/0xb0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
INFO: task kworker/0:1:2236 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:1 D ffffffff81814e20 0 2236 2 0x00000080
Workqueue: ceph-msgr con_work [libceph]
ffff88003aafba58 0000000000000046 ffff88003aafbfd8 0000000000014480
ffff88003aafa010 0000000000014480 0000000000014480 0000000000014480
ffff88003aafbfd8 0000000000014480 ffff88003c2fd080 ffffffff81c13480
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffff811c77da>] __wait_on_freeing_inode+0x9a/0xc0
[<ffffffff8108c240>] ? wake_atomic_t_function+0x40/0x40
[<ffffffffa02a5844>] ? fill_inode+0x5e4/0x7a0 [ceph]
[<ffffffffa02a32a0>] ? ceph_mount+0x1e0/0x1e0 [ceph]
[<ffffffff811c7950>] find_inode+0xa0/0xd0
[<ffffffffa02a32a0>] ? ceph_mount+0x1e0/0x1e0 [ceph]
[<ffffffff811c989f>] iget5_locked+0x5f/0x1c0
[<ffffffffa02a32d0>] ? ceph_ino_compare+0x30/0x30 [ceph]
[<ffffffffa02a4dcc>] ceph_get_inode+0x2c/0x70 [ceph]
[<ffffffffa02a7292>] ? ceph_init_dentry+0xc2/0xf0 [ceph]
[<ffffffffa02a646a>] ceph_readdir_prepopulate+0x42a/0x520 [ceph]
[<ffffffffa02ba8f2>] handle_reply+0x3f2/0x530 [ceph]
[<ffffffffa02bbbf3>] dispatch+0xe3/0x190 [ceph]
[<ffffffffa02710ab>] process_message+0xab/0xd0 [libceph]
[<ffffffffa0274212>] try_read+0x2d2/0x430 [libceph]
[<ffffffffa0274700>] con_work+0xc0/0x230 [libceph]
[<ffffffff8108458c>] process_one_work+0x17c/0x420
[<ffffffff810859f3>] worker_thread+0x123/0x400
[<ffffffff810858d0>] ? manage_workers+0x170/0x170
[<ffffffff8108b96e>] kthread+0xce/0xe0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
[<ffffffff8160fbfc>] ret_from_fork+0x7c/0xb0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
INFO: task grep:6376 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
grep D ffffffff81814e20 0 6376 6371 0x00000080
ffff88003ad95998 0000000000000082 ffff88003ad95fd8 0000000000014480
ffff88003ad94010 0000000000014480 0000000000014480 0000000000014480
ffff88003ad95fd8 0000000000014480 ffff880037079140 ffffffff81c13480
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffffa01a3b55>] __fscache_wait_on_page_write+0x75/0xb0 [fscache]
[<ffffffff8108c1c0>] ? wake_up_bit+0x40/0x40
[<ffffffff811a5175>] ? __mem_cgroup_uncharge_common+0xd5/0x2d0
[<ffffffffa02bda8a>] ceph_invalidate_fscache_page+0x2a/0x50 [ceph]
[<ffffffffa02aac6f>] ceph_invalidatepage+0x5f/0xc0 [ceph]
[<ffffffff8114f0a5>] do_invalidatepage+0x25/0x30
[<ffffffff8114f34f>] truncate_inode_page+0x8f/0xa0
[<ffffffff8114fa37>] truncate_inode_pages_range+0x1a7/0x630
[<ffffffff811d6c69>] ? __inode_wait_for_writeback+0x69/0xc0
[<ffffffff8108c240>] ? wake_atomic_t_function+0x40/0x40
[<ffffffff8114ff45>] truncate_inode_pages+0x15/0x20
[<ffffffff811c880e>] evict+0x1ae/0x1d0
[<ffffffff811c891f>] iput_final+0xef/0x190
[<ffffffff811c89fe>] iput+0x3e/0x50
[<ffffffff811c58c8>] dentry_kill+0x1b8/0x200
[<ffffffff811c5ce4>] dput+0x64/0x100
[<ffffffff811bbc08>] lookup_fast+0x298/0x2b0
[<ffffffff811bc215>] path_lookupat+0x105/0x750
[<ffffffff8116d466>] ? handle_pte_fault+0xe6/0x210
[<ffffffff8105bff7>] ? pte_alloc_one+0x37/0x50
[<ffffffff811bc894>] filename_lookup+0x34/0xc0
[<ffffffff811bdbd9>] user_path_at_empty+0x59/0xa0
[<ffffffff8160b090>] ? __do_page_fault+0x280/0x4f0
[<ffffffff811bdc31>] user_path_at+0x11/0x20
[<ffffffff811b3529>] vfs_fstatat+0x59/0xb0
[<ffffffff811b367b>] vfs_stat+0x1b/0x20
[<ffffffff811b369f>] SYSC_newstat+0x1f/0x50
[<ffffffff8160b30e>] ? do_page_fault+0xe/0x10
[<ffffffff816077d8>] ? page_fault+0x28/0x30
[<ffffffff811b36de>] SyS_newstat+0xe/0x10
[<ffffffff8160fca9>] system_call_fastpath+0x16/0x1b
INFO: task find:6381 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
find D 0000000000000000 0 6381 1380 0x00000084
ffff8800387abd58 0000000000000086 ffff8800387abfd8 0000000000014480
ffff8800387aa010 0000000000014480 0000000000014480 0000000000014480
ffff8800387abfd8 0000000000014480 ffff880037cbf380 ffff880039f1ce80
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffff816056ce>] schedule_preempt_disabled+0xe/0x10
[<ffffffff81603f70>] __mutex_lock_slowpath+0x1a0/0x240
[<ffffffff81605a7e>] ? wait_for_completion_killable+0xbe/0x170
[<ffffffff8109d040>] ? try_to_wake_up+0x2c0/0x2c0
[<ffffffff81604033>] mutex_lock+0x23/0x40
[<ffffffffa02bb0d7>] ceph_mdsc_do_request+0x167/0x1b0 [ceph]
[<ffffffffa02a78c1>] ceph_readdir+0x241/0x660 [ceph]
[<ffffffff811c12f5>] iterate_dir+0xb5/0xe0
[<ffffffff811c14b5>] SyS_getdents+0x95/0x100
[<ffffffff811c1140>] ? SyS_ioctl+0xb0/0xb0
[<ffffffff8160fca9>] system_call_fastpath+0x16/0x1b
INFO: task kworker/0:0:6382 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:0 D 0000000000000000 0 6382 2 0x00000080
Workqueue: events delayed_work [ceph]
ffff880037653bd8 0000000000000046 ffff880037653fd8 0000000000014480
ffff880037652010 0000000000014480 0000000000014480 0000000000014480
ffff880037653fd8 0000000000014480 ffff88003c33e8c0 ffff8800000942c0
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffff816056ce>] schedule_preempt_disabled+0xe/0x10
[<ffffffff81603f70>] __mutex_lock_slowpath+0x1a0/0x240
[<ffffffffa02ae385>] ? ceph_cap_string+0xe5/0x100 [ceph]
[<ffffffff81604033>] mutex_lock+0x23/0x40
[<ffffffffa02b145d>] ceph_check_caps+0x38d/0x780 [ceph]
[<ffffffffa02b19df>] ceph_check_delayed_caps+0x7f/0xb0 [ceph]
[<ffffffffa02b81dc>] delayed_work+0x2c/0x1e0 [ceph]
[<ffffffff8108458c>] process_one_work+0x17c/0x420
[<ffffffff810859f3>] worker_thread+0x123/0x400
[<ffffffff810858d0>] ? manage_workers+0x170/0x170
[<ffffffff8108b96e>] kthread+0xce/0xe0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
[<ffffffff8160fbfc>] ret_from_fork+0x7c/0xb0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
INFO: task kworker/0:1:2236 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:1 D ffffffff81814e20 0 2236 2 0x00000080
Workqueue: ceph-msgr con_work [libceph]
ffff88003aafba58 0000000000000046 ffff88003aafbfd8 0000000000014480
ffff88003aafa010 0000000000014480 0000000000014480 0000000000014480
ffff88003aafbfd8 0000000000014480 ffff88003c2fd080 ffffffff81c13480
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffff811c77da>] __wait_on_freeing_inode+0x9a/0xc0
[<ffffffff8108c240>] ? wake_atomic_t_function+0x40/0x40
[<ffffffffa02a5844>] ? fill_inode+0x5e4/0x7a0 [ceph]
[<ffffffffa02a32a0>] ? ceph_mount+0x1e0/0x1e0 [ceph]
[<ffffffff811c7950>] find_inode+0xa0/0xd0
[<ffffffffa02a32a0>] ? ceph_mount+0x1e0/0x1e0 [ceph]
[<ffffffff811c989f>] iget5_locked+0x5f/0x1c0
[<ffffffffa02a32d0>] ? ceph_ino_compare+0x30/0x30 [ceph]
[<ffffffffa02a4dcc>] ceph_get_inode+0x2c/0x70 [ceph]
[<ffffffffa02a7292>] ? ceph_init_dentry+0xc2/0xf0 [ceph]
[<ffffffffa02a646a>] ceph_readdir_prepopulate+0x42a/0x520 [ceph]
[<ffffffffa02ba8f2>] handle_reply+0x3f2/0x530 [ceph]
[<ffffffffa02bbbf3>] dispatch+0xe3/0x190 [ceph]
[<ffffffffa02710ab>] process_message+0xab/0xd0 [libceph]
[<ffffffffa0274212>] try_read+0x2d2/0x430 [libceph]
[<ffffffffa0274700>] con_work+0xc0/0x230 [libceph]
[<ffffffff8108458c>] process_one_work+0x17c/0x420
[<ffffffff810859f3>] worker_thread+0x123/0x400
[<ffffffff810858d0>] ? manage_workers+0x170/0x170
[<ffffffff8108b96e>] kthread+0xce/0xe0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
[<ffffffff8160fbfc>] ret_from_fork+0x7c/0xb0
[<ffffffff8108b8a0>] ? kthread_freezable_should_stop+0x70/0x70
INFO: task grep:6376 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
grep D ffffffff81814e20 0 6376 6371 0x00000080
ffff88003ad95998 0000000000000082 ffff88003ad95fd8 0000000000014480
ffff88003ad94010 0000000000014480 0000000000014480 0000000000014480
ffff88003ad95fd8 0000000000014480 ffff880037079140 ffffffff81c13480
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffffa01a3b55>] __fscache_wait_on_page_write+0x75/0xb0 [fscache]
[<ffffffff8108c1c0>] ? wake_up_bit+0x40/0x40
[<ffffffff811a5175>] ? __mem_cgroup_uncharge_common+0xd5/0x2d0
[<ffffffffa02bda8a>] ceph_invalidate_fscache_page+0x2a/0x50 [ceph]
[<ffffffffa02aac6f>] ceph_invalidatepage+0x5f/0xc0 [ceph]
[<ffffffff8114f0a5>] do_invalidatepage+0x25/0x30
[<ffffffff8114f34f>] truncate_inode_page+0x8f/0xa0
[<ffffffff8114fa37>] truncate_inode_pages_range+0x1a7/0x630
[<ffffffff811d6c69>] ? __inode_wait_for_writeback+0x69/0xc0
[<ffffffff8108c240>] ? wake_atomic_t_function+0x40/0x40
[<ffffffff8114ff45>] truncate_inode_pages+0x15/0x20
[<ffffffff811c880e>] evict+0x1ae/0x1d0
[<ffffffff811c891f>] iput_final+0xef/0x190
[<ffffffff811c89fe>] iput+0x3e/0x50
[<ffffffff811c58c8>] dentry_kill+0x1b8/0x200
[<ffffffff811c5ce4>] dput+0x64/0x100
[<ffffffff811bbc08>] lookup_fast+0x298/0x2b0
[<ffffffff811bc215>] path_lookupat+0x105/0x750
[<ffffffff8116d466>] ? handle_pte_fault+0xe6/0x210
[<ffffffff8105bff7>] ? pte_alloc_one+0x37/0x50
[<ffffffff811bc894>] filename_lookup+0x34/0xc0
[<ffffffff811bdbd9>] user_path_at_empty+0x59/0xa0
[<ffffffff8160b090>] ? __do_page_fault+0x280/0x4f0
[<ffffffff811bdc31>] user_path_at+0x11/0x20
[<ffffffff811b3529>] vfs_fstatat+0x59/0xb0
[<ffffffff811b367b>] vfs_stat+0x1b/0x20
[<ffffffff811b369f>] SYSC_newstat+0x1f/0x50
[<ffffffff8160b30e>] ? do_page_fault+0xe/0x10
[<ffffffff816077d8>] ? page_fault+0x28/0x30
[<ffffffff811b36de>] SyS_newstat+0xe/0x10
[<ffffffff8160fca9>] system_call_fastpath+0x16/0x1b
INFO: task find:6381 blocked for more than 120 seconds.
Not tainted 3.12.6-1.fks.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
find D 0000000000000000 0 6381 1380 0x00000084
ffff8800387abd58 0000000000000086 ffff8800387abfd8 0000000000014480
ffff8800387aa010 0000000000014480 0000000000014480 0000000000014480
ffff8800387abfd8 0000000000014480 ffff880037cbf380 ffff880039f1ce80
Call Trace:
[<ffffffff81605569>] schedule+0x29/0x70
[<ffffffff816056ce>] schedule_preempt_disabled+0xe/0x10
[<ffffffff81603f70>] __mutex_lock_slowpath+0x1a0/0x240
[<ffffffff81605a7e>] ? wait_for_completion_killable+0xbe/0x170
[<ffffffff8109d040>] ? try_to_wake_up+0x2c0/0x2c0
[<ffffffff81604033>] mutex_lock+0x23/0x40
[<ffffffffa02bb0d7>] ceph_mdsc_do_request+0x167/0x1b0 [ceph]
[<ffffffffa02a78c1>] ceph_readdir+0x241/0x660 [ceph]
[<ffffffff811c12f5>] iterate_dir+0xb5/0xe0
[<ffffffff811c14b5>] SyS_getdents+0x95/0x100
[<ffffffff811c1140>] ? SyS_ioctl+0xb0/0xb0
[<ffffffff8160fca9>] system_call_fastpath+0x16/0x1b