2009-04-07 16:35:16

by Miklos Szeredi

[permalink] [raw]
Subject: [bug] lockdep warning: module_mutex vs. ftrace_lock

=======================================================
[ INFO: possible circular locking dependency detected ]
2.6.29-09854-gd508afb-dirty #6
-------------------------------------------------------
modprobe/3184 is trying to acquire lock:
(ftrace_lock){+.+.+.}, at: [<ffffffff80277e71>] ftrace_convert_nops+0x32/0x267

but task is already holding lock:
(module_mutex){+.+.+.}, at: [<ffffffff8026a539>] sys_init_module+0x3f/0x1d3

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #1 (module_mutex){+.+.+.}:
[<ffffffff8026134a>] __lock_acquire+0x12fe/0x1668
[<ffffffff802617a2>] lock_acquire+0xee/0x112
[<ffffffff804fe0a6>] mutex_lock_nested+0x4f/0x305
[<ffffffff8026709e>] module_update_tracepoints+0x1c/0x73
[<ffffffff80274f74>] tracepoint_update_probes+0x21/0x23
[<ffffffff8027510a>] tracepoint_probe_register+0x4a/0x68
[<ffffffff80277cae>] register_ftrace_graph+0x2a9/0x30f
[<ffffffff8027f928>] trace_selftest_startup_function_graph+0x2e/0xbb
[<ffffffff8027fdc5>] register_tracer+0x151/0x26e
[<ffffffff8070b942>] init_graph_trace+0x10/0x12
[<ffffffff80209066>] do_one_initcall+0x5b/0x135
[<ffffffff806fa5e4>] kernel_init+0x12f/0x185
[<ffffffff8020c2ba>] child_rip+0xa/0x20
[<ffffffffffffffff>] 0xffffffffffffffff

-> #0 (ftrace_lock){+.+.+.}:
[<ffffffff80261067>] __lock_acquire+0x101b/0x1668
[<ffffffff802617a2>] lock_acquire+0xee/0x112
[<ffffffff804fe0a6>] mutex_lock_nested+0x4f/0x305
[<ffffffff80277e71>] ftrace_convert_nops+0x32/0x267
[<ffffffff802780bd>] ftrace_init_module+0x17/0x19
[<ffffffff8026a011>] load_module+0x1122/0x160b
[<ffffffff8026a556>] sys_init_module+0x5c/0x1d3
[<ffffffff8020b21b>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff

other info that might help us debug this:

1 lock held by modprobe/3184:
#0: (module_mutex){+.+.+.}, at: [<ffffffff8026a539>] sys_init_module+0x3f/0x1d3

stack backtrace:
Pid: 3184, comm: modprobe Not tainted 2.6.29-09854-gd508afb-dirty #6
Call Trace:
[<ffffffff8025fba1>] print_circular_bug_tail+0xc5/0xd0
[<ffffffff80261067>] __lock_acquire+0x101b/0x1668
[<ffffffff80267905>] ? find_symbol_in_section+0x39/0xda
[<ffffffff80266a52>] ? each_symbol_in_section+0x3a/0x7a
[<ffffffff802617a2>] lock_acquire+0xee/0x112
[<ffffffff80277e71>] ? ftrace_convert_nops+0x32/0x267
[<ffffffff804fe0a6>] mutex_lock_nested+0x4f/0x305
[<ffffffff80277e71>] ? ftrace_convert_nops+0x32/0x267
[<ffffffff8020af16>] ? ftrace_call+0x5/0x2b
[<ffffffff80277e71>] ftrace_convert_nops+0x32/0x267
[<ffffffff802780bd>] ftrace_init_module+0x17/0x19
[<ffffffff8026a011>] load_module+0x1122/0x160b
[<ffffffff8025f3a5>] ? trace_hardirqs_on_caller+0x114/0x138
[<ffffffff8026a556>] sys_init_module+0x5c/0x1d3
[<ffffffff8020b21b>] system_call_fastpath+0x16/0x1b


2009-04-07 18:30:29

by Frederic Weisbecker

[permalink] [raw]
Subject: Re: [bug] lockdep warning: module_mutex vs. ftrace_lock

On Tue, Apr 07, 2009 at 06:34:56PM +0200, Miklos Szeredi wrote:
> =======================================================
> [ INFO: possible circular locking dependency detected ]
> 2.6.29-09854-gd508afb-dirty #6
> -------------------------------------------------------
> modprobe/3184 is trying to acquire lock:
> (ftrace_lock){+.+.+.}, at: [<ffffffff80277e71>] ftrace_convert_nops+0x32/0x267
>
> but task is already holding lock:
> (module_mutex){+.+.+.}, at: [<ffffffff8026a539>] sys_init_module+0x3f/0x1d3
>
> which lock already depends on the new lock.
>
>
> the existing dependency chain (in reverse order) is:
>
> -> #1 (module_mutex){+.+.+.}:
> [<ffffffff8026134a>] __lock_acquire+0x12fe/0x1668
> [<ffffffff802617a2>] lock_acquire+0xee/0x112
> [<ffffffff804fe0a6>] mutex_lock_nested+0x4f/0x305
> [<ffffffff8026709e>] module_update_tracepoints+0x1c/0x73
> [<ffffffff80274f74>] tracepoint_update_probes+0x21/0x23
> [<ffffffff8027510a>] tracepoint_probe_register+0x4a/0x68
> [<ffffffff80277cae>] register_ftrace_graph+0x2a9/0x30f
> [<ffffffff8027f928>] trace_selftest_startup_function_graph+0x2e/0xbb
> [<ffffffff8027fdc5>] register_tracer+0x151/0x26e
> [<ffffffff8070b942>] init_graph_trace+0x10/0x12
> [<ffffffff80209066>] do_one_initcall+0x5b/0x135
> [<ffffffff806fa5e4>] kernel_init+0x12f/0x185
> [<ffffffff8020c2ba>] child_rip+0xa/0x20
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> -> #0 (ftrace_lock){+.+.+.}:
> [<ffffffff80261067>] __lock_acquire+0x101b/0x1668
> [<ffffffff802617a2>] lock_acquire+0xee/0x112
> [<ffffffff804fe0a6>] mutex_lock_nested+0x4f/0x305
> [<ffffffff80277e71>] ftrace_convert_nops+0x32/0x267
> [<ffffffff802780bd>] ftrace_init_module+0x17/0x19
> [<ffffffff8026a011>] load_module+0x1122/0x160b
> [<ffffffff8026a556>] sys_init_module+0x5c/0x1d3
> [<ffffffff8020b21b>] system_call_fastpath+0x16/0x1b
> [<ffffffffffffffff>] 0xffffffffffffffff



Ah that's this ftrace/modules lock dependency that Steven told me about
recently. Steven, do you know more about it now?

Thanks.
Frederic.


> other info that might help us debug this:
>
> 1 lock held by modprobe/3184:
> #0: (module_mutex){+.+.+.}, at: [<ffffffff8026a539>] sys_init_module+0x3f/0x1d3
>
> stack backtrace:
> Pid: 3184, comm: modprobe Not tainted 2.6.29-09854-gd508afb-dirty #6
> Call Trace:
> [<ffffffff8025fba1>] print_circular_bug_tail+0xc5/0xd0
> [<ffffffff80261067>] __lock_acquire+0x101b/0x1668
> [<ffffffff80267905>] ? find_symbol_in_section+0x39/0xda
> [<ffffffff80266a52>] ? each_symbol_in_section+0x3a/0x7a
> [<ffffffff802617a2>] lock_acquire+0xee/0x112
> [<ffffffff80277e71>] ? ftrace_convert_nops+0x32/0x267
> [<ffffffff804fe0a6>] mutex_lock_nested+0x4f/0x305
> [<ffffffff80277e71>] ? ftrace_convert_nops+0x32/0x267
> [<ffffffff8020af16>] ? ftrace_call+0x5/0x2b
> [<ffffffff80277e71>] ftrace_convert_nops+0x32/0x267
> [<ffffffff802780bd>] ftrace_init_module+0x17/0x19
> [<ffffffff8026a011>] load_module+0x1122/0x160b
> [<ffffffff8025f3a5>] ? trace_hardirqs_on_caller+0x114/0x138
> [<ffffffff8026a556>] sys_init_module+0x5c/0x1d3
> [<ffffffff8020b21b>] system_call_fastpath+0x16/0x1b
> --
> 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/

2009-04-13 14:09:18

by Steven Rostedt

[permalink] [raw]
Subject: Re: [bug] lockdep warning: module_mutex vs. ftrace_lock

Sorry for the late reply, I just got back from San Fran, and I do not
check my Red Hat email while I'm traveling.


On Tue, 2009-04-07 at 20:30 +0200, Frederic Weisbecker wrote:
> On Tue, Apr 07, 2009 at 06:34:56PM +0200, Miklos Szeredi wrote:
> > =======================================================
> > [ INFO: possible circular locking dependency detected ]
> > 2.6.29-09854-gd508afb-dirty #6
> > -------------------------------------------------------
> > modprobe/3184 is trying to acquire lock:
> > (ftrace_lock){+.+.+.}, at: [<ffffffff80277e71>] ftrace_convert_nops+0x32/0x267
> >
> > but task is already holding lock:
> > (module_mutex){+.+.+.}, at: [<ffffffff8026a539>] sys_init_module+0x3f/0x1d3
> >
> > which lock already depends on the new lock.
> >
> >
> > the existing dependency chain (in reverse order) is:
> >
> > -> #1 (module_mutex){+.+.+.}:
> > [<ffffffff8026134a>] __lock_acquire+0x12fe/0x1668
> > [<ffffffff802617a2>] lock_acquire+0xee/0x112
> > [<ffffffff804fe0a6>] mutex_lock_nested+0x4f/0x305
> > [<ffffffff8026709e>] module_update_tracepoints+0x1c/0x73
> > [<ffffffff80274f74>] tracepoint_update_probes+0x21/0x23
> > [<ffffffff8027510a>] tracepoint_probe_register+0x4a/0x68
> > [<ffffffff80277cae>] register_ftrace_graph+0x2a9/0x30f
> > [<ffffffff8027f928>] trace_selftest_startup_function_graph+0x2e/0xbb
> > [<ffffffff8027fdc5>] register_tracer+0x151/0x26e
> > [<ffffffff8070b942>] init_graph_trace+0x10/0x12
> > [<ffffffff80209066>] do_one_initcall+0x5b/0x135
> > [<ffffffff806fa5e4>] kernel_init+0x12f/0x185
> > [<ffffffff8020c2ba>] child_rip+0xa/0x20
> > [<ffffffffffffffff>] 0xffffffffffffffff
> >
> > -> #0 (ftrace_lock){+.+.+.}:
> > [<ffffffff80261067>] __lock_acquire+0x101b/0x1668
> > [<ffffffff802617a2>] lock_acquire+0xee/0x112
> > [<ffffffff804fe0a6>] mutex_lock_nested+0x4f/0x305
> > [<ffffffff80277e71>] ftrace_convert_nops+0x32/0x267
> > [<ffffffff802780bd>] ftrace_init_module+0x17/0x19
> > [<ffffffff8026a011>] load_module+0x1122/0x160b
> > [<ffffffff8026a556>] sys_init_module+0x5c/0x1d3
> > [<ffffffff8020b21b>] system_call_fastpath+0x16/0x1b
> > [<ffffffffffffffff>] 0xffffffffffffffff
>
>
>
> Ah that's this ftrace/modules lock dependency that Steven told me about
> recently. Steven, do you know more about it now?

Yeah, I think I submitted a patch to fix that. I'll check my repo.

-- Steve