vfs: hung task at path_openat

From: Sasha Levin
Date: Thu Mar 29 2012 - 14:43:01 EST


Hi all,

I seem to be getting the spew at the bottom with latest linux-next.

Seems like all processes block within path_openat.

[ 3361.521323] INFO: task trinity:3095 blocked for more than 120 seconds.
[ 3361.522042] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3361.522746] trinity D ffff880075280000 3248 3095 1 0x00000000
[ 3361.523458] ffff880073debb88 0000000000000082 ffff880073debb18
ffff880075280000
[ 3361.524244] ffff880073debfd8 00000000001d4580 ffff880073dea010
00000000001d4580
[ 3361.525068] 00000000001d4580 00000000001d4580 ffff880073debfd8
00000000001d4580
[ 3361.525813] Call Trace:
[ 3361.526084] [<ffffffff82706114>] schedule+0x24/0x70
[ 3361.526488] [<ffffffff827064e3>] schedule_preempt_disabled+0x13/0x20
[ 3361.527616] [<ffffffff82704683>] __mutex_lock_common+0x1e3/0x5c0
[ 3361.528614] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.529437] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.530304] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.531140] [<ffffffff82704b90>] mutex_lock_nested+0x40/0x50
[ 3361.531971] [<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.532806] [<ffffffff817c9a17>] ? security_inode_permission+0x17/0x20
[ 3361.533782] [<ffffffff811f2579>] link_path_walk+0x119/0x3b0
[ 3361.534638] [<ffffffff811eefd0>] ? generic_readlink+0xb0/0xb0
[ 3361.535501] [<ffffffff81897568>] ? __raw_spin_lock_init+0x38/0x70
[ 3361.536412] [<ffffffff811f2e2a>] path_openat+0xba/0x500
[ 3361.537185] [<ffffffff810ed8a0>] ? sched_clock_cpu+0xd0/0x120
[ 3361.538035] [<ffffffff811f3384>] do_filp_open+0x44/0xa0
[ 3361.538813] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.539642] [<ffffffff82707ab0>] ? _raw_spin_unlock+0x30/0x60
[ 3361.540496] [<ffffffff81202925>] ? alloc_fd+0x145/0x260
[ 3361.541290] [<ffffffff811e23a3>] do_sys_open+0x103/0x1e0
[ 3361.542096] [<ffffffff811e24bc>] sys_open+0x1c/0x20
[ 3361.542795] [<ffffffff82708a39>] system_call_fastpath+0x16/0x1b
[ 3361.543678] 1 lock held by trinity/3095:
[ 3361.544260] #0: (&type->i_mutex_dir_key){+.+.+.}, at:
[<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.545648] INFO: task trinity:3097 blocked for more than 120 seconds.
[ 3361.546594] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3361.547715] trinity D ffff880073e23000 3648 3097 1 0x00000000
[ 3361.548784] ffff880073e31b88 0000000000000082 ffff880073e31b18
ffff880073e23000
[ 3361.549937] ffff880073e31fd8 00000000001d4580 ffff880073e30010
00000000001d4580
[ 3361.551123] 00000000001d4580 00000000001d4580 ffff880073e31fd8
00000000001d4580
[ 3361.552199] Call Trace:
[ 3361.552406] [<ffffffff82706114>] schedule+0x24/0x70
[ 3361.552810] [<ffffffff827064e3>] schedule_preempt_disabled+0x13/0x20
[ 3361.553390] [<ffffffff82704683>] __mutex_lock_common+0x1e3/0x5c0
[ 3361.554126] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.554898] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.555756] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.556546] [<ffffffff82704b90>] mutex_lock_nested+0x40/0x50
[ 3361.557393] [<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.558193] [<ffffffff817c9a17>] ? security_inode_permission+0x17/0x20
[ 3361.559157] [<ffffffff811f2579>] link_path_walk+0x119/0x3b0
[ 3361.559970] [<ffffffff811eefd0>] ? generic_readlink+0xb0/0xb0
[ 3361.560841] [<ffffffff81897568>] ? __raw_spin_lock_init+0x38/0x70
[ 3361.561767] [<ffffffff811f2e2a>] path_openat+0xba/0x500
[ 3361.562570] [<ffffffff810ed8a0>] ? sched_clock_cpu+0xd0/0x120
[ 3361.563458] [<ffffffff811f3384>] do_filp_open+0x44/0xa0
[ 3361.564318] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.565155] [<ffffffff82707ab0>] ? _raw_spin_unlock+0x30/0x60
[ 3361.566055] [<ffffffff81202925>] ? alloc_fd+0x145/0x260
[ 3361.566836] [<ffffffff811e23a3>] do_sys_open+0x103/0x1e0
[ 3361.567650] [<ffffffff811e24bc>] sys_open+0x1c/0x20
[ 3361.568376] [<ffffffff82708a39>] system_call_fastpath+0x16/0x1b
[ 3361.569335] 1 lock held by trinity/3097:
[ 3361.569919] #0: (&type->i_mutex_dir_key){+.+.+.}, at:
[<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.571328] INFO: task trinity:3099 blocked for more than 120 seconds.
[ 3361.572270] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3361.573403] trinity D ffff880073e3b000 3992 3099 1 0x00000000
[ 3361.574478] ffff880073e85b88 0000000000000082 ffff880073e85b18
ffff880073e3b000
[ 3361.575708] ffff880073e85fd8 00000000001d4580 ffff880073e84010
00000000001d4580
[ 3361.576932] 00000000001d4580 00000000001d4580 ffff880073e85fd8
00000000001d4580
[ 3361.578211] Call Trace:33175 99%
[ 3361.578582] [<ffffffff82706114>] schedule+0x24/0x70
[ 3361.579393] [<ffffffff827064e3>] schedule_preempt_disabled+0x13/0x20
[ 3361.580410] [<ffffffff82704683>] __mutex_lock_common+0x1e3/0x5c0
[ 3361.581382] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.582270] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.583161] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.583962] [<ffffffff82704b90>] mutex_lock_nested+0x40/0x50
[ 3361.584887] [<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.585737] [<ffffffff817c9a17>] ? security_inode_permission+0x17/0x20
[ 3361.586448] [<ffffffff811f2579>] link_path_walk+0x119/0x3b0
[ 3361.587180] [<ffffffff811eefd0>] ? generic_readlink+0xb0/0xb0
[ 3361.587994] [<ffffffff81897568>] ? __raw_spin_lock_init+0x38/0x70
[ 3361.588542] [<ffffffff811f2e2a>] path_openat+0xba/0x500
[ 3361.589308] [<ffffffff810ed8a0>] ? sched_clock_cpu+0xd0/0x120
[ 3361.590180] [<ffffffff811f3384>] do_filp_open+0x44/0xa0
[ 3361.590952] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.591782] [<ffffffff82707ab0>] ? _raw_spin_unlock+0x30/0x60
[ 3361.592663] [<ffffffff81202925>] ? alloc_fd+0x145/0x260
[ 3361.593459] [<ffffffff811e23a3>] do_sys_open+0x103/0x1e0
[ 3361.594277] [<ffffffff811e24bc>] sys_open+0x1c/0x20
[ 3361.595056] [<ffffffff82708a39>] system_call_fastpath+0x16/0x1b
[ 3361.595951] 1 lock held by trinity/3099:
[ 3361.596567] #0: (&type->i_mutex_dir_key){+.+.+.}, at:
[<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.597983] INFO: task trinity:3101 blocked for more than 120 seconds.
[ 3361.598977] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3361.600134] trinity D ffff880073e38000 3552 3101 1 0x00000000
[ 3361.601188] ffff880073df1b88 0000000000000082 ffff880073df1b18
ffff880073e38000
[ 3361.602386] ffff880073df1fd8 00000000001d4580 ffff880073df0010
00000000001d4580
[ 3361.603566] 00000000001d4580 00000000001d4580 ffff880073df1fd8
00000000001d4580
[ 3361.604539] Call Trace:33175 99%
[ 3361.604756] [<ffffffff82706114>] schedule+0x24/0x70
[ 3361.605209] [<ffffffff827064e3>] schedule_preempt_disabled+0x13/0x20
[ 3361.605860] [<ffffffff82704683>] __mutex_lock_common+0x1e3/0x5c0
[ 3361.606772] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.607558] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.608380] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.609181] [<ffffffff82704b90>] mutex_lock_nested+0x40/0x50
[ 3361.610055] [<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.610819] [<ffffffff817c9a17>] ? security_inode_permission+0x17/0x20
[ 3361.611787] [<ffffffff811f2579>] link_path_walk+0x119/0x3b0
[ 3361.612624] [<ffffffff811eefd0>] ? generic_readlink+0xb0/0xb0
[ 3361.613477] [<ffffffff81897568>] ? __raw_spin_lock_init+0x38/0x70
[ 3361.614387] [<ffffffff811f2e2a>] path_openat+0xba/0x500
[ 3361.615154] [<ffffffff810ed8a0>] ? sched_clock_cpu+0xd0/0x120
[ 3361.615988] [<ffffffff811f3384>] do_filp_open+0x44/0xa0
[ 3361.616463] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.617190] [<ffffffff82707ab0>] ? _raw_spin_unlock+0x30/0x60
[ 3361.618071] [<ffffffff81202925>] ? alloc_fd+0x145/0x260
[ 3361.618858] [<ffffffff811e23a3>] do_sys_open+0x103/0x1e0
[ 3361.619677] [<ffffffff811e24bc>] sys_open+0x1c/0x20
[ 3361.620473] [<ffffffff82708a39>] system_call_fastpath+0x16/0x1b
[ 3361.621376] 1 lock held by trinity/3101:
[ 3361.621957] #0: (&type->i_mutex_dir_key){+.+.+.}, at:
[<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.623184] INFO: task trinity:3103 blocked for more than 120 seconds.
[ 3361.623799] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3361.624492] trinity D ffff880073ea3000 3560 3103 1 0x00000000
[ 3361.625313] ffff880073e93b88 0000000000000082 ffff880073e93b18
ffff880073ea3000
[ 3361.626272] ffff880073e93fd8 00000000001d4580 ffff880073e92010
00000000001d4580
[ 3361.627326] 00000000001d4580 00000000001d4580 ffff880073e93fd8
00000000001d4580
[ 3361.628472] Call Trace:33175 99%
[ 3361.628838] [<ffffffff82706114>] schedule+0x24/0x70
[ 3361.629582] [<ffffffff827064e3>] schedule_preempt_disabled+0x13/0x20
[ 3361.630541] [<ffffffff82704683>] __mutex_lock_common+0x1e3/0x5c0
[ 3361.631450] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.632263] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.633112] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.633912] [<ffffffff82704b90>] mutex_lock_nested+0x40/0x50
[ 3361.634797] [<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.635281] [<ffffffff817c9a17>] ? security_inode_permission+0x17/0x20
[ 3361.636006] [<ffffffff811f2579>] link_path_walk+0x119/0x3b0
[ 3361.636527] [<ffffffff811eefd0>] ? generic_readlink+0xb0/0xb0
[ 3361.637050] [<ffffffff81897568>] ? __raw_spin_lock_init+0x38/0x70
[ 3361.637556] [<ffffffff811f2e2a>] path_openat+0xba/0x500
[ 3361.638317] [<ffffffff810ed8a0>] ? sched_clock_cpu+0xd0/0x120
[ 3361.639177] [<ffffffff811f3384>] do_filp_open+0x44/0xa0
[ 3361.639962] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.640792] [<ffffffff82707ab0>] ? _raw_spin_unlock+0x30/0x60
[ 3361.641657] [<ffffffff81202925>] ? alloc_fd+0x145/0x260
[ 3361.642542] [<ffffffff811e23a3>] do_sys_open+0x103/0x1e0
[ 3361.643340] [<ffffffff811e24bc>] sys_open+0x1c/0x20
[ 3361.644100] [<ffffffff82708a39>] system_call_fastpath+0x16/0x1b
[ 3361.644981] 1 lock held by trinity/3103:
[ 3361.645595] #0: (&type->i_mutex_dir_key){+.+.+.}, at:
[<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.647046] INFO: task trinity:3105 blocked for more than 120 seconds.
[ 3361.647966] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3361.649152] trinity D ffff880073ea0000 3816 3105 1 0x00000000
[ 3361.650237] ffff880073ec9b88 0000000000000082 ffff880073ec9b18
ffff880073ea0000
[ 3361.651385] ffff880073ec9fd8 00000000001d4580 ffff880073ec8010
00000000001d4580
[ 3361.652581] 00000000001d4580 00000000001d4580 ffff880073ec9fd8
00000000001d4580
[ 3361.653467] Call Trace:33175 99%
[ 3361.653720] [<ffffffff82706114>] schedule+0x24/0x70
[ 3361.654234] [<ffffffff827064e3>] schedule_preempt_disabled+0x13/0x20
[ 3361.654798] [<ffffffff82704683>] __mutex_lock_common+0x1e3/0x5c0
[ 3361.655774] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.656284] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.656736] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.657236] [<ffffffff82704b90>] mutex_lock_nested+0x40/0x50
[ 3361.657734] [<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.658209] [<ffffffff817c9a17>] ? security_inode_permission+0x17/0x20
[ 3361.658741] [<ffffffff811f2579>] link_path_walk+0x119/0x3b0
[ 3361.659264] [<ffffffff811eefd0>] ? generic_readlink+0xb0/0xb0
[ 3361.659751] [<ffffffff81897568>] ? __raw_spin_lock_init+0x38/0x70
[ 3361.660299] [<ffffffff811f2e2a>] path_openat+0xba/0x500
[ 3361.660733] [<ffffffff810ed8a0>] ? sched_clock_cpu+0xd0/0x120
[ 3361.661304] [<ffffffff811f3384>] do_filp_open+0x44/0xa0
[ 3361.661750] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.662682] [<ffffffff82707ab0>] ? _raw_spin_unlock+0x30/0x60
[ 3361.663560] [<ffffffff81202925>] ? alloc_fd+0x145/0x260
[ 3361.664356] [<ffffffff811e23a3>] do_sys_open+0x103/0x1e0
[ 3361.665171] [<ffffffff811e24bc>] sys_open+0x1c/0x20
[ 3361.665918] [<ffffffff82708a39>] system_call_fastpath+0x16/0x1b
[ 3361.666834] 1 lock held by trinity/3105:
[ 3361.667437] #0: (&type->i_mutex_dir_key){+.+.+.}, at:
[<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.668848] INFO: task kworker/u:2:16016 blocked for more than 120 seconds.
[ 3361.669982] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 3361.671108] kworker/u:2 D ffff88006b2b3000 5416 16016 12176 0x00000000
[ 3361.672230] ffff8800063c19c0 0000000000000082 ffff8800063c1950
ffff88006b2b3000
[ 3361.673378] ffff8800063c1fd8 00000000001d4580 ffff8800063c0010
00000000001d4580
[ 3361.674560] 00000000001d4580 00000000001d4580 ffff8800063c1fd8
00000000001d4580
[ 3361.675738] Call Trace:33175 99%
[ 3361.676108] [<ffffffff82706114>] schedule+0x24/0x70
[ 3361.676803] [<ffffffff827064e3>] schedule_preempt_disabled+0x13/0x20
[ 3361.677782] [<ffffffff82704683>] __mutex_lock_common+0x1e3/0x5c0
[ 3361.678670] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.679455] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.680264] [<ffffffff811f1480>] ? do_lookup+0x260/0x3b0
[ 3361.681109] [<ffffffff82704b90>] mutex_lock_nested+0x40/0x50
[ 3361.681957] [<ffffffff811f1480>] do_lookup+0x260/0x3b0
[ 3361.682838] [<ffffffff817c9a17>] ? security_inode_permission+0x17/0x20
[ 3361.683862] [<ffffffff811f2579>] link_path_walk+0x119/0x3b0
[ 3361.684709] [<ffffffff811eefd0>] ? generic_readlink+0xb0/0xb0
[ 3361.685561] [<ffffffff81897568>] ? __raw_spin_lock_init+0x38/0x70
[ 3361.686483] [<ffffffff811f2e2a>] path_openat+0xba/0x500
[ 3361.687278] [<ffffffff81057263>] ? sched_clock+0x13/0x20
[ 3361.687722] [<ffffffff810ed765>] ? sched_clock_local+0x25/0x90
[ 3361.688582] [<ffffffff810ed8a0>] ? sched_clock_cpu+0xd0/0x120
[ 3361.689456] [<ffffffff811f3384>] do_filp_open+0x44/0xa0
[ 3361.690222] [<ffffffff81119abd>] ? __lock_release+0x8d/0x1d0
[ 3361.691097] [<ffffffff810e3531>] ? get_parent_ip+0x11/0x50
[ 3361.691906] [<ffffffff810e38fd>] ? sub_preempt_count+0x9d/0xd0
[ 3361.692857] [<ffffffff82707ab0>] ? _raw_spin_unlock+0x30/0x60
[ 3361.693733] [<ffffffff811eb0fd>] open_exec+0x2d/0xf0
[ 3361.694465] [<ffffffff811ec238>] do_execve_common+0x128/0x320
[ 3361.695313] [<ffffffff811ec4b5>] do_execve+0x35/0x40
[ 3361.696083] [<ffffffff810589f5>] sys_execve+0x45/0x70
[ 3361.696842] [<ffffffff82709ee8>] kernel_execve+0x68/0xd0
[ 3361.697663] [<ffffffff810cd5e6>] ? ____call_usermodehelper+0xf6/0x130
[ 3361.698641] [<ffffffff810cd639>] call_helper+0x19/0x20
[ 3361.699419] [<ffffffff82709e74>] kernel_thread_helper+0x4/0x10
[ 3361.700206] [<ffffffff810e3ee0>] ? finish_task_switch+0x80/0x110
[ 3361.700782] [<ffffffff82708174>] ? retint_restore_args+0x13/0x13
[ 3361.701676] [<ffffffff810cd620>] ? ____call_usermodehelper+0x130/0x130
[ 3361.702473] [<ffffffff82709e70>] ? gs_change+0x13/0x13
[ 3361.703258] 2 locks held by kworker/u:2/16016:
[ 3361.703895] #0: (&sig->cred_guard_mutex){+.+.+.}, at:
[<ffffffff811e9872>] prepare_bprm_creds+0x32/0x80
[ 3361.705376] #1: (&type->i_mutex_dir_key){+.+.+.}, at:
[<ffffffff811f1480>] do_lookup+0x260/0x3b0
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/