Skip to contentSkip to conversation

New: inconsistent lock state at boot

Bug 16617 Andrew Morton 2 participants 2 messages Aug 23, 2010 1 message not in the archive

Subsystems (2)
Networking Network drivers
lore
Share & tools
lore

Andrew Morton

author
#1 lore raw
In reply to a message not in the archive

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

Quoted 110 lines · On Tue, 17 Aug 2010 20:05:55 GMT [email protected] wrote:

https://bugzilla.kernel.org/show_bug.cgi?id=16617

Summary: inconsistent lock state at boot
Product: Memory Management
Version: 2.5
Kernel Version: 2.6.36-rc1
Platform: All
OS/Version: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: Other
AssignedTo: [email protected]
ReportedBy: [email protected]
Regression: Yes

Kernel 2.6.36-rc1
Athlon64 X2 4200 in 64bit mode
Slackware64 13.1
1 GB RAM

Since 2.6.36-rc1 with debug options activated (lock validation, kmemcheck, etc.), I get the following error at boot:

ADDRCONF(NETDEV_UP): eth0: link is not ready
uli526x: eth0 NIC Link is Up 100 Mbps Full duplex
ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

=================================
[ INFO: inconsistent lock state ]
2.6.36-rc1 #2
---------------------------------
inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage. iptables/1915 [HC0[0]:SC0[0]:HE1:SE1] takes:
(&(&lock->lock)->rlock){+.?...}, at: [<ffffffff814d7c01>]
get_counters+0x111/0x1c0
{IN-SOFTIRQ-W} state was registered at:

  [<ffffffff81074e66>] __lock_acquire+0xb96/0x1c10
  [<ffffffff81075f3a>] lock_acquire+0x5a/0x70
  [<ffffffff81595996>] _raw_spin_lock+0x36/0x50
  [<ffffffff8152bfc8>] ip6t_do_table+0x88/0x4e0
  [<ffffffff8152e437>] ip6table_filter_hook+0x17/0x20
  [<ffffffff8147ef54>] nf_iterate+0x64/0xa0
  [<ffffffff8147f034>] nf_hook_slow+0xa4/0x150
  [<ffffffff815196ab>] mld_sendpack+0x28b/0x4d0
  [<ffffffff8151a10b>] mld_ifc_timer_expire+0x27b/0x310
  [<ffffffff8104fade>] run_timer_softirq+0x1ae/0x2e0
  [<ffffffff810499a0>] __do_softirq+0xc0/0x160
  [<ffffffff8100324c>] call_softirq+0x1c/0x30
  [<ffffffff81005585>] do_softirq+0x75/0xb0
  [<ffffffff810494d5>] irq_exit+0x95/0xa0
  [<ffffffff8101f5fa>] smp_apic_timer_interrupt+0x6a/0xa0
  [<ffffffff81002d13>] apic_timer_interrupt+0x13/0x20
  [<ffffffff81165c1d>] ext4_lookup+0x9d/0x110
  [<ffffffff810d8f1b>] do_lookup+0x1db/0x270
  [<ffffffff810db135>] link_path_walk+0x445/0xbe0
  [<ffffffff810dba40>] path_walk+0x60/0xe0
  [<ffffffff810dbbc3>] do_path_lookup+0x53/0x60
  [<ffffffff810dc803>] user_path_at+0x53/0xa0
  [<ffffffff810d2ed7>] vfs_fstatat+0x37/0x70
  [<ffffffff810d2f46>] vfs_stat+0x16/0x20
  [<ffffffff810d311f>] sys_newstat+0x1f/0x50
  [<ffffffff810023ab>] system_call_fastpath+0x16/0x1b
irq event stamp: 73961
hardirqs last  enabled at (73961): [<ffffffff810497ae>]
local_bh_enable+0x7e/0x100
hardirqs last disabled at (73959): [<ffffffff81049761>]
local_bh_enable+0x31/0x100
softirqs last  enabled at (73960): [<ffffffff814d7b6b>] get_counters+0x7b/0x1c0
softirqs last disabled at (73914): [<ffffffff814d7b1e>] get_counters+0x2e/0x1c0

other info that might help us debug this:
2 locks held by iptables/1915:
#0: (sk_lock-AF_INET){+.+.+.}, at: [<ffffffff8149c35a>]

ip_getsockopt+0x6a/0xb0
 #1:  (&xt[i].mutex){+.+.+.}, at: [<ffffffff8148ac4e>]
xt_find_table_lock+0x3e/0x120

stack backtrace:
Pid: 1915, comm: iptables Not tainted 2.6.36-rc1 #2
Call Trace:
 [<ffffffff81072371>] print_usage_bug+0x181/0x1d0
 [<ffffffff810727d9>] mark_lock+0x419/0x630
 [<ffffffff81074edc>] __lock_acquire+0xc0c/0x1c10
 [<ffffffff815957b8>] ? trace_hardirqs_off_thunk+0x3a/0x3c
 [<ffffffff815957b8>] ? trace_hardirqs_off_thunk+0x3a/0x3c
 [<ffffffff815957b8>] ? trace_hardirqs_off_thunk+0x3a/0x3c
 [<ffffffff81075f3a>] lock_acquire+0x5a/0x70
 [<ffffffff814d7c01>] ? get_counters+0x111/0x1c0
 [<ffffffff81072d2d>] ? trace_hardirqs_on_caller+0x13d/0x180
 [<ffffffff81595996>] _raw_spin_lock+0x36/0x50
 [<ffffffff814d7c01>] ? get_counters+0x111/0x1c0
 [<ffffffff810497ae>] ? local_bh_enable+0x7e/0x100
 [<ffffffff814d7c01>] get_counters+0x111/0x1c0
 [<ffffffff814d7cde>] alloc_counters+0x2e/0x50
 [<ffffffff814d94cd>] ? do_ipt_get_ctl+0xfd/0x3a0
 [<ffffffff814d95b1>] do_ipt_get_ctl+0x1e1/0x3a0
 [<ffffffff81072d7d>] ? trace_hardirqs_on+0xd/0x10
 [<ffffffff814808b0>] nf_sockopt+0x90/0xa0
 [<ffffffff814808d3>] nf_getsockopt+0x13/0x20
 [<ffffffff8149c370>] ip_getsockopt+0x80/0xb0
 [<ffffffff814ba391>] raw_getsockopt+0x11/0x30
 [<ffffffff8145242f>] sock_common_getsockopt+0xf/0x20
 [<ffffffff8144f3d0>] sys_getsockopt+0x60/0xc0
 [<ffffffff810023ab>] system_call_fastpath+0x16/0x1b

I haven't managed to find the faulty module.

#2 lore raw
Quoted 116 lines · Andrew Morton

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

Quoted 110 lines · On Tue, 17 Aug 2010 20:05:55 GMT [email protected] wrote:

https://bugzilla.kernel.org/show_bug.cgi?id=16617

Summary: inconsistent lock state at boot
Product: Memory Management
Version: 2.5
Kernel Version: 2.6.36-rc1
Platform: All
OS/Version: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: Other
AssignedTo: [email protected]
ReportedBy: [email protected]
Regression: Yes

Kernel 2.6.36-rc1
Athlon64 X2 4200 in 64bit mode
Slackware64 13.1
1 GB RAM

Since 2.6.36-rc1 with debug options activated (lock validation, kmemcheck, etc.), I get the following error at boot:

ADDRCONF(NETDEV_UP): eth0: link is not ready
uli526x: eth0 NIC Link is Up 100 Mbps Full duplex
ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

=================================
[ INFO: inconsistent lock state ]
2.6.36-rc1 #2
---------------------------------
inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage. iptables/1915 [HC0[0]:SC0[0]:HE1:SE1] takes:
(&(&lock->lock)->rlock){+.?...}, at: [<ffffffff814d7c01>]
get_counters+0x111/0x1c0
{IN-SOFTIRQ-W} state was registered at:

  [<ffffffff81074e66>] __lock_acquire+0xb96/0x1c10
  [<ffffffff81075f3a>] lock_acquire+0x5a/0x70
  [<ffffffff81595996>] _raw_spin_lock+0x36/0x50
  [<ffffffff8152bfc8>] ip6t_do_table+0x88/0x4e0
  [<ffffffff8152e437>] ip6table_filter_hook+0x17/0x20
  [<ffffffff8147ef54>] nf_iterate+0x64/0xa0
  [<ffffffff8147f034>] nf_hook_slow+0xa4/0x150
  [<ffffffff815196ab>] mld_sendpack+0x28b/0x4d0
  [<ffffffff8151a10b>] mld_ifc_timer_expire+0x27b/0x310
  [<ffffffff8104fade>] run_timer_softirq+0x1ae/0x2e0
  [<ffffffff810499a0>] __do_softirq+0xc0/0x160
  [<ffffffff8100324c>] call_softirq+0x1c/0x30
  [<ffffffff81005585>] do_softirq+0x75/0xb0
  [<ffffffff810494d5>] irq_exit+0x95/0xa0
  [<ffffffff8101f5fa>] smp_apic_timer_interrupt+0x6a/0xa0
  [<ffffffff81002d13>] apic_timer_interrupt+0x13/0x20
  [<ffffffff81165c1d>] ext4_lookup+0x9d/0x110
  [<ffffffff810d8f1b>] do_lookup+0x1db/0x270
  [<ffffffff810db135>] link_path_walk+0x445/0xbe0
  [<ffffffff810dba40>] path_walk+0x60/0xe0
  [<ffffffff810dbbc3>] do_path_lookup+0x53/0x60
  [<ffffffff810dc803>] user_path_at+0x53/0xa0
  [<ffffffff810d2ed7>] vfs_fstatat+0x37/0x70
  [<ffffffff810d2f46>] vfs_stat+0x16/0x20
  [<ffffffff810d311f>] sys_newstat+0x1f/0x50
  [<ffffffff810023ab>] system_call_fastpath+0x16/0x1b
irq event stamp: 73961
hardirqs last  enabled at (73961): [<ffffffff810497ae>]
local_bh_enable+0x7e/0x100
hardirqs last disabled at (73959): [<ffffffff81049761>]
local_bh_enable+0x31/0x100
softirqs last  enabled at (73960): [<ffffffff814d7b6b>] get_counters+0x7b/0x1c0
softirqs last disabled at (73914): [<ffffffff814d7b1e>] get_counters+0x2e/0x1c0

other info that might help us debug this:
2 locks held by iptables/1915:
#0: (sk_lock-AF_INET){+.+.+.}, at: [<ffffffff8149c35a>]

ip_getsockopt+0x6a/0xb0
 #1:  (&xt[i].mutex){+.+.+.}, at: [<ffffffff8148ac4e>]
xt_find_table_lock+0x3e/0x120

stack backtrace:
Pid: 1915, comm: iptables Not tainted 2.6.36-rc1 #2
Call Trace:
 [<ffffffff81072371>] print_usage_bug+0x181/0x1d0
 [<ffffffff810727d9>] mark_lock+0x419/0x630
 [<ffffffff81074edc>] __lock_acquire+0xc0c/0x1c10
 [<ffffffff815957b8>] ? trace_hardirqs_off_thunk+0x3a/0x3c
 [<ffffffff815957b8>] ? trace_hardirqs_off_thunk+0x3a/0x3c
 [<ffffffff815957b8>] ? trace_hardirqs_off_thunk+0x3a/0x3c
 [<ffffffff81075f3a>] lock_acquire+0x5a/0x70
 [<ffffffff814d7c01>] ? get_counters+0x111/0x1c0
 [<ffffffff81072d2d>] ? trace_hardirqs_on_caller+0x13d/0x180
 [<ffffffff81595996>] _raw_spin_lock+0x36/0x50
 [<ffffffff814d7c01>] ? get_counters+0x111/0x1c0
 [<ffffffff810497ae>] ? local_bh_enable+0x7e/0x100
 [<ffffffff814d7c01>] get_counters+0x111/0x1c0
 [<ffffffff814d7cde>] alloc_counters+0x2e/0x50
 [<ffffffff814d94cd>] ? do_ipt_get_ctl+0xfd/0x3a0
 [<ffffffff814d95b1>] do_ipt_get_ctl+0x1e1/0x3a0
 [<ffffffff81072d7d>] ? trace_hardirqs_on+0xd/0x10
 [<ffffffff814808b0>] nf_sockopt+0x90/0xa0
 [<ffffffff814808d3>] nf_getsockopt+0x13/0x20
 [<ffffffff8149c370>] ip_getsockopt+0x80/0xb0
 [<ffffffff814ba391>] raw_getsockopt+0x11/0x30
 [<ffffffff8145242f>] sock_common_getsockopt+0xf/0x20
 [<ffffffff8144f3d0>] sys_getsockopt+0x60/0xc0
 [<ffffffff810023ab>] system_call_fastpath+0x16/0x1b

I haven't managed to find the faulty module.

Already fixed in Linus tree

commit 001389b9581c13fe5fc357a0f89234f85af4215d

Author: Eric Dumazet <[email protected]>
Date:   Mon Aug 16 10:22:10 2010 +0000

netfilter: {ip,ip6,arp}_tables: avoid lockdep false positive

After commit 24b36f019 (netfilter: {ip,ip6,arp}_tables: dont block bottom half more than necessary), lockdep can raise a warning because we attempt to lock a spinlock with BH enabled, while the same lock is usually locked by another cpu in a softirq context.

Disable again BH to avoid these lockdep warnings.

Reported-by Linus Torvalds <[email protected]>
Diagnosed-by David S. Miller <[email protected]>
Signed-off-by Eric Dumazet <[email protected]>
Signed-off-by David S. Miller <[email protected]>