ftrace 2.6.30-rc4: possible circular locking dependency

ftrace 2.6.30-rc4: possible circular locking dependency

[Tetsuo Handa]

Hello.

I got this.

[    7.153662] Write protecting the kernel read-only data: 2172k
[    7.155593] Testing CPA: undo c0718000-c0937000
[    7.156809] Testing CPA: write protecting again
[    7.677561] 
[    7.677570] =======================================================
[    7.678536] [ INFO: possible circular locking dependency detected ]
[    7.678536] 2.6.30-rc4 #1
[    7.678536] -------------------------------------------------------
[    7.678536] insmod/571 is trying to acquire lock:
[    7.678536]  (ftrace_lock){+.+.+.}, at: [<c048e862>] ftrace_convert_nops+0x1f/0x1dc
[    7.678536] 
[    7.678536] but task is already holding lock:
[    7.678536]  (module_mutex){+.+.+.}, at: [<c0472637>] sys_init_module+0x3a/0x1ff
[    7.678536] 
[    7.678536] which lock already depends on the new lock.
[    7.678536] 
[    7.678536] 
[    7.678536] the existing dependency chain (in reverse order) is:
[    7.678536] 
[    7.678536] -> #1 (module_mutex){+.+.+.}:
[    7.678536]        [<c046762e>] __lock_acquire+0x931/0xad4
[    7.678536]        [<c0467861>] lock_acquire+0x90/0xad
[    7.678536]        [<c0710d46>] __mutex_lock_common+0x3a/0x4b6
[    7.678536]        [<c0711269>] mutex_lock_nested+0x33/0x3b
[    7.678536]        [<c0470709>] module_update_tracepoints+0x15/0x6d
[    7.678536]        [<c048bd7c>] tracepoint_update_probes+0x1c/0x1e
[    7.678536]        [<c048c186>] tracepoint_probe_register+0x50/0x5f
[    7.678536]        [<c048e6f1>] register_ftrace_graph+0x1ec/0x245
[    7.678536]        [<c0493763>] trace_selftest_startup_function_graph+0x23/0x9d
[    7.678536]        [<c0493e38>] register_tracer+0xf7/0x1fe
[    7.678536]        [<c0abb66d>] init_graph_trace+0xd/0xf
[    7.678536]        [<c040116a>] do_one_initcall+0x78/0x1d5
[    7.678536]        [<c0aa26de>] kernel_init+0x13b/0x1a9
[    7.678536]        [<c0403f9b>] kernel_thread_helper+0x7/0x10
[    7.678536]        [<ffffffff>] 0xffffffff
[    7.678536] 
[    7.678536] -> #0 (ftrace_lock){+.+.+.}:
[    7.678536]        [<c0467540>] __lock_acquire+0x843/0xad4
[    7.678536]        [<c0467861>] lock_acquire+0x90/0xad
[    7.678536]        [<c0710d46>] __mutex_lock_common+0x3a/0x4b6
[    7.678536]        [<c0711269>] mutex_lock_nested+0x33/0x3b
[    7.678536]        [<c048e862>] ftrace_convert_nops+0x1f/0x1dc
[    7.678536]        [<c048ea34>] ftrace_init_module+0x15/0x17
[    7.678536]        [<c0471cbc>] load_module+0x1122/0x17c1
[    7.678536]        [<c0472661>] sys_init_module+0x64/0x1ff
[    7.678536]        [<c0403575>] syscall_call+0x7/0xb
[    7.678536]        [<ffffffff>] 0xffffffff
[    7.678536] 
[    7.678536] other info that might help us debug this:
[    7.678536] 
[    7.678536] 1 lock held by insmod/571:
[    7.678536]  #0:  (module_mutex){+.+.+.}, at: [<c0472637>] sys_init_module+0x3a/0x1ff
[    7.678536] 
[    7.678536] stack backtrace:
[    7.678536] Pid: 571, comm: insmod Not tainted 2.6.30-rc4 #1
[    7.678536] Call Trace:
[    7.678536]  [<c0465d39>] print_circular_bug_tail+0x5d/0x68
[    7.678536]  [<c0467540>] __lock_acquire+0x843/0xad4
[    7.678536]  [<c0467861>] lock_acquire+0x90/0xad
[    7.678536]  [<c048e862>] ? ftrace_convert_nops+0x1f/0x1dc
[    7.678536]  [<c0710d46>] __mutex_lock_common+0x3a/0x4b6
[    7.678536]  [<c048e862>] ? ftrace_convert_nops+0x1f/0x1dc
[    7.678536]  [<c0403fc7>] ? ftrace_call+0x5/0x8
[    7.678536]  [<c0711269>] mutex_lock_nested+0x33/0x3b
[    7.678536]  [<c048e862>] ? ftrace_convert_nops+0x1f/0x1dc
[    7.678536]  [<c048e862>] ftrace_convert_nops+0x1f/0x1dc
[    7.678536]  [<c048ea34>] ftrace_init_module+0x15/0x17
[    7.678536]  [<c0471cbc>] load_module+0x1122/0x17c1
[    7.678536]  [<c0464125>] ? debug_mutex_free_waiter+0x25/0x81
[    7.678536]  [<c0472661>] sys_init_module+0x64/0x1ff
[    7.678536]  [<c0403575>] syscall_call+0x7/0xb
[    7.807546] insmod used greatest stack depth: 2328 bytes left
[    7.912357] Fusion MPT base driver 3.04.07

Environment is CentOS 5.3(i686) on VMware.
Config is at http://I-love.SAKURA.ne.jp/tmp/config-2.6.30-rc4
Full message is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.30-rc4.txt

Regards.

Re: ftrace 2.6.30-rc4: possible circular locking dependency

[Steven Rostedt]

Hi Tetsuo,

Thanks for the report. But we already have a fix for it. But the change is 
a bit of design change, and it is one of those things that is hard to know 
if we should push it up stream this late in the RCs.

We probably should. But the change affects two different subsystems. It 
affects ftrace as well as the module code. There's a bit of changes to the 
module code (Rusty being the maintainer) where we would be more 
comfortable if it goes via Rusty.

Rusty and Ingo,

What is the best way to get this change upstream?

Reference: http://lkml.org/lkml/2009/4/15/548

tip git SHA1: 93eb677d74a4f7d3edfb678c94f6c0544d9fbad2

-- Steve


On Fri, 8 May 2009, Tetsuo Handa wrote:

> Hello.
> 
> I got this.
> 
> [    7.153662] Write protecting the kernel read-only data: 2172k
> [    7.155593] Testing CPA: undo c0718000-c0937000
> [    7.156809] Testing CPA: write protecting again
> [    7.677561] 
> [    7.677570] =======================================================
> [    7.678536] [ INFO: possible circular locking dependency detected ]
> [    7.678536] 2.6.30-rc4 #1
> [    7.678536] -------------------------------------------------------
> [    7.678536] insmod/571 is trying to acquire lock:
> [    7.678536]  (ftrace_lock){+.+.+.}, at: [<c048e862>] ftrace_convert_nops+0x1f/0x1dc
> [    7.678536] 
> [    7.678536] but task is already holding lock:
> [    7.678536]  (module_mutex){+.+.+.}, at: [<c0472637>] sys_init_module+0x3a/0x1ff
> [    7.678536] 
> [    7.678536] which lock already depends on the new lock.
> [    7.678536] 
> [    7.678536] 
> [    7.678536] the existing dependency chain (in reverse order) is:
> [    7.678536] 
> [    7.678536] -> #1 (module_mutex){+.+.+.}:
> [    7.678536]        [<c046762e>] __lock_acquire+0x931/0xad4
> [    7.678536]        [<c0467861>] lock_acquire+0x90/0xad
> [    7.678536]        [<c0710d46>] __mutex_lock_common+0x3a/0x4b6
> [    7.678536]        [<c0711269>] mutex_lock_nested+0x33/0x3b
> [    7.678536]        [<c0470709>] module_update_tracepoints+0x15/0x6d
> [    7.678536]        [<c048bd7c>] tracepoint_update_probes+0x1c/0x1e
> [    7.678536]        [<c048c186>] tracepoint_probe_register+0x50/0x5f
> [    7.678536]        [<c048e6f1>] register_ftrace_graph+0x1ec/0x245
> [    7.678536]        [<c0493763>] trace_selftest_startup_function_graph+0x23/0x9d
> [    7.678536]        [<c0493e38>] register_tracer+0xf7/0x1fe
> [    7.678536]        [<c0abb66d>] init_graph_trace+0xd/0xf
> [    7.678536]        [<c040116a>] do_one_initcall+0x78/0x1d5
> [    7.678536]        [<c0aa26de>] kernel_init+0x13b/0x1a9
> [    7.678536]        [<c0403f9b>] kernel_thread_helper+0x7/0x10
> [    7.678536]        [<ffffffff>] 0xffffffff
> [    7.678536] 
> [    7.678536] -> #0 (ftrace_lock){+.+.+.}:
> [    7.678536]        [<c0467540>] __lock_acquire+0x843/0xad4
> [    7.678536]        [<c0467861>] lock_acquire+0x90/0xad
> [    7.678536]        [<c0710d46>] __mutex_lock_common+0x3a/0x4b6
> [    7.678536]        [<c0711269>] mutex_lock_nested+0x33/0x3b
> [    7.678536]        [<c048e862>] ftrace_convert_nops+0x1f/0x1dc
> [    7.678536]        [<c048ea34>] ftrace_init_module+0x15/0x17
> [    7.678536]        [<c0471cbc>] load_module+0x1122/0x17c1
> [    7.678536]        [<c0472661>] sys_init_module+0x64/0x1ff
> [    7.678536]        [<c0403575>] syscall_call+0x7/0xb
> [    7.678536]        [<ffffffff>] 0xffffffff
> [    7.678536] 
> [    7.678536] other info that might help us debug this:
> [    7.678536] 
> [    7.678536] 1 lock held by insmod/571:
> [    7.678536]  #0:  (module_mutex){+.+.+.}, at: [<c0472637>] sys_init_module+0x3a/0x1ff
> [    7.678536] 
> [    7.678536] stack backtrace:
> [    7.678536] Pid: 571, comm: insmod Not tainted 2.6.30-rc4 #1
> [    7.678536] Call Trace:
> [    7.678536]  [<c0465d39>] print_circular_bug_tail+0x5d/0x68
> [    7.678536]  [<c0467540>] __lock_acquire+0x843/0xad4
> [    7.678536]  [<c0467861>] lock_acquire+0x90/0xad
> [    7.678536]  [<c048e862>] ? ftrace_convert_nops+0x1f/0x1dc
> [    7.678536]  [<c0710d46>] __mutex_lock_common+0x3a/0x4b6
> [    7.678536]  [<c048e862>] ? ftrace_convert_nops+0x1f/0x1dc
> [    7.678536]  [<c0403fc7>] ? ftrace_call+0x5/0x8
> [    7.678536]  [<c0711269>] mutex_lock_nested+0x33/0x3b
> [    7.678536]  [<c048e862>] ? ftrace_convert_nops+0x1f/0x1dc
> [    7.678536]  [<c048e862>] ftrace_convert_nops+0x1f/0x1dc
> [    7.678536]  [<c048ea34>] ftrace_init_module+0x15/0x17
> [    7.678536]  [<c0471cbc>] load_module+0x1122/0x17c1
> [    7.678536]  [<c0464125>] ? debug_mutex_free_waiter+0x25/0x81
> [    7.678536]  [<c0472661>] sys_init_module+0x64/0x1ff
> [    7.678536]  [<c0403575>] syscall_call+0x7/0xb
> [    7.807546] insmod used greatest stack depth: 2328 bytes left
> [    7.912357] Fusion MPT base driver 3.04.07
> 
> Environment is CentOS 5.3(i686) on VMware.
> Config is at http://I-love.SAKURA.ne.jp/tmp/config-2.6.30-rc4
> Full message is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.30-rc4.txt
> 
> Regards.
> 

Re: ftrace 2.6.30-rc4: possible circular locking dependency

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> Hi Tetsuo,
> 
> Thanks for the report. But we already have a fix for it. But the change is 
> a bit of design change, and it is one of those things that is hard to know 
> if we should push it up stream this late in the RCs.
> 
> We probably should. But the change affects two different subsystems. It 
> affects ftrace as well as the module code. There's a bit of changes to the 
> module code (Rusty being the maintainer) where we would be more 
> comfortable if it goes via Rusty.
> 
> Rusty and Ingo,
> 
> What is the best way to get this change upstream?
> 
> Reference: http://lkml.org/lkml/2009/4/15/548
> 
> tip git SHA1: 93eb677d74a4f7d3edfb678c94f6c0544d9fbad2

Would be nice to have a non-conflicting version against latest -git 
- which Tetsuo could test as well, and which i could apply if the 
test is successful.

	Ingo

Re: ftrace 2.6.30-rc4: possible circular locking dependency

[Steven Rostedt]

On Fri, 8 May 2009, Ingo Molnar wrote:

> 
> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > 
> > Hi Tetsuo,
> > 
> > Thanks for the report. But we already have a fix for it. But the change is 
> > a bit of design change, and it is one of those things that is hard to know 
> > if we should push it up stream this late in the RCs.
> > 
> > We probably should. But the change affects two different subsystems. It 
> > affects ftrace as well as the module code. There's a bit of changes to the 
> > module code (Rusty being the maintainer) where we would be more 
> > comfortable if it goes via Rusty.
> > 
> > Rusty and Ingo,
> > 
> > What is the best way to get this change upstream?
> > 
> > Reference: http://lkml.org/lkml/2009/4/15/548
> > 
> > tip git SHA1: 93eb677d74a4f7d3edfb678c94f6c0544d9fbad2
> 
> Would be nice to have a non-conflicting version against latest -git 
> - which Tetsuo could test as well, and which i could apply if the 
> test is successful.

OK, I'll write up a patch.

-- Steve

Re: ftrace 2.6.30-rc4: possible circular locking dependency

[Tetsuo Handa]

Steven Rostedt wrote:
> 
> On Fri, 8 May 2009, Ingo Molnar wrote:
> 
> > Would be nice to have a non-conflicting version against latest -git 
> > - which Tetsuo could test as well, and which i could apply if the 
> > test is successful.
> 
> OK, I'll write up a patch.
> 
Is the patch ready? I want to try the patch in my 2.6.30-rc6 environment.