Hi all,
While fuzzing with trinity inside a KVM tools guest running latest -next kernel
I've stumbled on the following:
[ 450.180599] ===============================
[ 450.181392] [ INFO: suspicious RCU usage. ]
[ 450.182101] 3.9.0-rc1-next-20130305-sasha-00048-g35e9ec5-dirty #1032 Tainted: G W
[ 450.183482] -------------------------------
[ 450.184343] include/linux/cgroup.h:429 suspicious rcu_dereference_check() usage!
[ 450.185575]
[ 450.185575] other info that might help us debug this:
[ 450.185575]
[ 450.186961]
[ 450.186961] rcu_scheduler_active = 1, debug_locks = 1
[ 450.188001] 4 locks held by kworker/u:0/6:
[ 450.188646] #0: (khelper){.+.+.+}, at: [<ffffffff8112ba98>] process_one_work+0x238/0x570
[ 450.190186] #1: ((&sub_info->work)){+.+.+.}, at: [<ffffffff8112ba98>] process_one_work+0x238/0x570
[ 450.191824] #2: (&(&p->alloc_lock)->rlock){+.+.-.}, at: [<ffffffff812036d3>] dump_header+0x43/0xe0
[ 450.193366] #3: (cpuset_buffer_lock){+.+...}, at: [<ffffffff811a06d0>] cpuset_print_task_mems_allowed+0x60/0x150
[ 450.195281]
[ 450.195281] stack backtrace:
[ 450.195987] Pid: 6, comm: kworker/u:0 Tainted: G W 3.9.0-rc1-next-20130305-sasha-00048-g35e9ec5-dirty #1032
[ 450.197678] Call Trace:
[ 450.198086] [<ffffffff811793b3>] lockdep_rcu_suspicious+0x113/0x130
[ 450.199077] [<ffffffff811a0757>] cpuset_print_task_mems_allowed+0xe7/0x150
[ 450.200263] [<ffffffff8120370c>] dump_header+0x7c/0xe0
[ 450.201135] [<ffffffff81203972>] oom_kill_process+0x82/0x370
[ 450.202048] [<ffffffff812040cb>] out_of_memory+0x1ab/0x200
[ 450.202921] [<ffffffff83d44e00>] ? _raw_write_unlock_irq+0x50/0x80
[ 450.204068] [<ffffffff8120ad1f>] __alloc_pages_slowpath+0x5bf/0x700
[ 450.205075] [<ffffffff8120b135>] __alloc_pages_nodemask+0x2d5/0x400
[ 450.206067] [<ffffffff811047c8>] dup_task_struct+0x68/0x1c0
[ 450.206975] [<ffffffff81105b19>] copy_process+0xe9/0xfd0
[ 450.207798] [<ffffffff8114dd25>] ? sched_clock_local+0x25/0x90
[ 450.208679] [<ffffffff81127c50>] ? call_helper+0x20/0x20
[ 450.209496] [<ffffffff81106e6b>] do_fork+0xbb/0x280
[ 450.210384] [<ffffffff811070b1>] kernel_thread+0x21/0x30
[ 450.211323] [<ffffffff81127a93>] __call_usermodehelper+0x33/0xa0
[ 450.212260] [<ffffffff8112bbc8>] process_one_work+0x368/0x570
[ 450.213201] [<ffffffff8112ba98>] ? process_one_work+0x238/0x570
[ 450.214248] [<ffffffff8112d735>] worker_thread+0x1f5/0x340
[ 450.215159] [<ffffffff8112d540>] ? manage_workers+0x160/0x160
[ 450.216078] [<ffffffff81135ec2>] kthread+0xe2/0xf0
[ 450.216901] [<ffffffff8117e34a>] ? __lock_release+0x1da/0x1f0
[ 450.217824] [<ffffffff81135de0>] ? __init_kthread_worker+0x70/0x70
[ 450.218791] [<ffffffff83d4ddbc>] ret_from_fork+0x7c/0xb0
[ 450.219627] [<ffffffff81135de0>] ? __init_kthread_worker+0x70/0x70
[ 450.220780] kworker/u:0 cpuset=/ mems_allowed=0
The offending commit looks like "cgroup: fix cgroup_path() vs rename() race".
Thanks,
Sasha
On 2013/3/7 0:02, Sasha Levin wrote:
> Hi all,
>
> While fuzzing with trinity inside a KVM tools guest running latest -next kernel
> I've stumbled on the following:
>
> [ 450.180599] ===============================
> [ 450.181392] [ INFO: suspicious RCU usage. ]
> [ 450.182101] 3.9.0-rc1-next-20130305-sasha-00048-g35e9ec5-dirty #1032 Tainted: G W
> [ 450.183482] -------------------------------
> [ 450.184343] include/linux/cgroup.h:429 suspicious rcu_dereference_check() usage!
My fault. I didn't trigger a OOM to test my patch. I thought the caller
of cpuset_print_task_mems_allowed() already acquired rcu_read_lock()...
Thanks for the report.
On 03/07/2013 12:02 AM, Sasha Levin wrote:
> Hi all,
>
> While fuzzing with trinity inside a KVM tools guest running latest -next kernel
> I've stumbled on the following:
>
> [ 450.180599] ===============================
> [ 450.181392] [ INFO: suspicious RCU usage. ]
> [ 450.182101] 3.9.0-rc1-next-20130305-sasha-00048-g35e9ec5-dirty #1032 Tainted: G W
> [ 450.183482] -------------------------------
> [ 450.184343] include/linux/cgroup.h:429 suspicious rcu_dereference_check() usage!
> [ 450.185575]
> [ 450.185575] other info that might help us debug this:
> [ 450.185575]
> [ 450.186961]
> [ 450.186961] rcu_scheduler_active = 1, debug_locks = 1
> [ 450.188001] 4 locks held by kworker/u:0/6:
> [ 450.188646] #0: (khelper){.+.+.+}, at: [<ffffffff8112ba98>] process_one_work+0x238/0x570
> [ 450.190186] #1: ((&sub_info->work)){+.+.+.}, at: [<ffffffff8112ba98>] process_one_work+0x238/0x570
> [ 450.191824] #2: (&(&p->alloc_lock)->rlock){+.+.-.}, at: [<ffffffff812036d3>] dump_header+0x43/0xe0
Hi, Sasha
I suppose this is the warn context:
cpuset_print_task_mems_allowed() -> task_cs() -> task_subsys_state()
and this is the definition of task_subsys_state():
#define task_subsys_state_check(task, subsys_id, __c) \
rcu_dereference_check(task->cgroups->subsys[subsys_id], \
lockdep_is_held(&task->alloc_lock) || \
cgroup_lock_is_held() || (__c))
the condition "lockdep_is_held(&task->alloc_lock)" should match (#2
lock), the warn doesn't make sense to me...
Regards,
Michael Wang
> [ 450.193366] #3: (cpuset_buffer_lock){+.+...}, at: [<ffffffff811a06d0>] cpuset_print_task_mems_allowed+0x60/0x150
> [ 450.195281]
> [ 450.195281] stack backtrace:
> [ 450.195987] Pid: 6, comm: kworker/u:0 Tainted: G W 3.9.0-rc1-next-20130305-sasha-00048-g35e9ec5-dirty #1032
> [ 450.197678] Call Trace:
> [ 450.198086] [<ffffffff811793b3>] lockdep_rcu_suspicious+0x113/0x130
> [ 450.199077] [<ffffffff811a0757>] cpuset_print_task_mems_allowed+0xe7/0x150
> [ 450.200263] [<ffffffff8120370c>] dump_header+0x7c/0xe0
> [ 450.201135] [<ffffffff81203972>] oom_kill_process+0x82/0x370
> [ 450.202048] [<ffffffff812040cb>] out_of_memory+0x1ab/0x200
> [ 450.202921] [<ffffffff83d44e00>] ? _raw_write_unlock_irq+0x50/0x80
> [ 450.204068] [<ffffffff8120ad1f>] __alloc_pages_slowpath+0x5bf/0x700
> [ 450.205075] [<ffffffff8120b135>] __alloc_pages_nodemask+0x2d5/0x400
> [ 450.206067] [<ffffffff811047c8>] dup_task_struct+0x68/0x1c0
> [ 450.206975] [<ffffffff81105b19>] copy_process+0xe9/0xfd0
> [ 450.207798] [<ffffffff8114dd25>] ? sched_clock_local+0x25/0x90
> [ 450.208679] [<ffffffff81127c50>] ? call_helper+0x20/0x20
> [ 450.209496] [<ffffffff81106e6b>] do_fork+0xbb/0x280
> [ 450.210384] [<ffffffff811070b1>] kernel_thread+0x21/0x30
> [ 450.211323] [<ffffffff81127a93>] __call_usermodehelper+0x33/0xa0
> [ 450.212260] [<ffffffff8112bbc8>] process_one_work+0x368/0x570
> [ 450.213201] [<ffffffff8112ba98>] ? process_one_work+0x238/0x570
> [ 450.214248] [<ffffffff8112d735>] worker_thread+0x1f5/0x340
> [ 450.215159] [<ffffffff8112d540>] ? manage_workers+0x160/0x160
> [ 450.216078] [<ffffffff81135ec2>] kthread+0xe2/0xf0
> [ 450.216901] [<ffffffff8117e34a>] ? __lock_release+0x1da/0x1f0
> [ 450.217824] [<ffffffff81135de0>] ? __init_kthread_worker+0x70/0x70
> [ 450.218791] [<ffffffff83d4ddbc>] ret_from_fork+0x7c/0xb0
> [ 450.219627] [<ffffffff81135de0>] ? __init_kthread_worker+0x70/0x70
> [ 450.220780] kworker/u:0 cpuset=/ mems_allowed=0
>
> The offending commit looks like "cgroup: fix cgroup_path() vs rename() race".
>
>
> Thanks,
> Sasha
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
On 2013/3/7 14:15, Michael Wang wrote:
> On 03/07/2013 12:02 AM, Sasha Levin wrote:
>> Hi all,
>>
>> While fuzzing with trinity inside a KVM tools guest running latest -next kernel
>> I've stumbled on the following:
>>
>> [ 450.180599] ===============================
>> [ 450.181392] [ INFO: suspicious RCU usage. ]
>> [ 450.182101] 3.9.0-rc1-next-20130305-sasha-00048-g35e9ec5-dirty #1032 Tainted: G W
>> [ 450.183482] -------------------------------
>> [ 450.184343] include/linux/cgroup.h:429 suspicious rcu_dereference_check() usage!
>> [ 450.185575]
>> [ 450.185575] other info that might help us debug this:
>> [ 450.185575]
>> [ 450.186961]
>> [ 450.186961] rcu_scheduler_active = 1, debug_locks = 1
>> [ 450.188001] 4 locks held by kworker/u:0/6:
>> [ 450.188646] #0: (khelper){.+.+.+}, at: [<ffffffff8112ba98>] process_one_work+0x238/0x570
>> [ 450.190186] #1: ((&sub_info->work)){+.+.+.}, at: [<ffffffff8112ba98>] process_one_work+0x238/0x570
>> [ 450.191824] #2: (&(&p->alloc_lock)->rlock){+.+.-.}, at: [<ffffffff812036d3>] dump_header+0x43/0xe0
>
> Hi, Sasha
>
> I suppose this is the warn context:
>
> cpuset_print_task_mems_allowed() -> task_cs() -> task_subsys_state()
>
> and this is the definition of task_subsys_state():
>
> #define task_subsys_state_check(task, subsys_id, __c) \
> rcu_dereference_check(task->cgroups->subsys[subsys_id], \
> lockdep_is_held(&task->alloc_lock) || \
> cgroup_lock_is_held() || (__c))
>
> the condition "lockdep_is_held(&task->alloc_lock)" should match (#2
> lock), the warn doesn't make sense to me...
>
nope..note this is 3.9-rc1-next, not 3.9-rc1.
The warning is from this:
/* Caller should hold rcu_read_lock() */
static inline const char *cgroup_name(const struct cgroup *cgrp)
{
return rcu_dereference(cgrp->name)->name;
}
I've cooked up a patch. Will send out today.