Re: 2.6.21-rc5-rt4 inconsistent lock state
Michal Piotrowski napisał(a):
> Hi,
[..]
> http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc5-rt4/rt-config
> http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc5-rt4/rt-dmesg
>
I just fixed an isic build in AT :)
BUG: isic:11396 task might have lost a preemption check!
[] dump_trace+0x78/0x21a
[] show_trace_log_lvl+0x35/0x54
[] show_trace+0x2c/0x2e
[] dump_stack+0x29/0x2b
[] preempt_enable_no_resched+0x5c/0x5e
[] debug_smp_processor_id+0xb0/0xb8
[] nf_conntrack_in+0x39c/0x468 [nf_conntrack]
[] ipv4_conntrack_local+0x61/0x67 [nf_conntrack_ipv4]
[] nf_iterate+0x40/0x71
[] nf_hook_slow+0x5c/0xd7
[] raw_sendmsg+0x518/0x6ee
[] inet_sendmsg+0x4b/0x55
[] sock_sendmsg+0xf7/0x114
[] sys_sendto+0xe5/0x105
[] sys_socketcall+0x17e/0x254
[] syscall_call+0x7/0xb
[] 0xb7f0c410
===
---
| preempt count: ]
| 0-level deep critical section nesting:
BUG: using smp_processor_id() in preemptible [] code: isic/16471
caller is nf_conntrack_in+0xd0/0x468 [nf_conntrack]
[] dump_trace+0x78/0x21a
[] show_trace_log_lvl+0x35/0x54
[] show_trace+0x2c/0x2e
[] dump_stack+0x29/0x2b
[] debug_smp_processor_id+0xab/0xb8
[] nf_conntrack_in+0xd0/0x468 [nf_conntrack]
[] ipv4_conntrack_local+0x61/0x67 [nf_conntrack_ipv4]
[] nf_iterate+0x40/0x71
[] nf_hook_slow+0x5c/0xd7
[] raw_sendmsg+0x518/0x6ee
[] inet_sendmsg+0x4b/0x55
[] sock_sendmsg+0xf7/0x114
[] sys_sendto+0xe5/0x105
[] sys_socketcall+0x17e/0x254
[] syscall_call+0x7/0xb
[] 0xb7f01410
===
---
| preempt count: 0001 ]
| 1-level deep critical section nesting:
.. [] __spin_lock+0x1a/0x59
.[] .. ( <= handle_fasteoi_irq+0x27/0xdf)
l *0xc0359d9e
0xc0359d9e is in __spin_lock (kernel/spinlock.c:218).
213 EXPORT_SYMBOL(__write_lock_bh);
214
215 void __lockfunc __spin_lock(raw_spinlock_t *lock)
216 {
217 preempt_disable();
218 spin_acquire(>dep_map, 0, 0, _RET_IP_);
219 _raw_spin_lock(lock);
220 }
221
222 EXPORT_SYMBOL(__spin_lock);
l *0xc016321a
0xc016321a is in handle_fasteoi_irq (kernel/irq/chip.c:405).
400 struct irqaction *action;
401 irqreturn_t action_ret;
402
403 spin_lock(>lock);
404
405 if (unlikely(desc->status & IRQ_INPROGRESS))
406 goto out;
407
408 desc->status &= ~(IRQ_REPLAY | IRQ_WAITING);
409 kstat_cpu(cpu).irqs[irq]++;
BUG: using smp_processor_id() in preemptible [] code: isic/16471
caller is nf_conntrack_in+0x43d/0x468 [nf_conntrack]
[] dump_trace+0x78/0x21a
[] show_trace_log_lvl+0x35/0x54
[] show_trace+0x2c/0x2e
[] dump_stack+0x29/0x2b
[] debug_smp_processor_id+0xab/0xb8
[] nf_conntrack_in+0x43d/0x468 [nf_conntrack]
[] ipv4_conntrack_local+0x61/0x67 [nf_conntrack_ipv4]
[] nf_iterate+0x40/0x71
[] nf_hook_slow+0x5c/0xd7
[] raw_sendmsg+0x518/0x6ee
[] inet_sendmsg+0x4b/0x55
[] sock_sendmsg+0xf7/0x114
[] sys_sendto+0xe5/0x105
[] sys_socketcall+0x17e/0x254
[] syscall_call+0x7/0xb
[] 0xb7f01410
===
---
| preempt count: 0001 ]
| 1-level deep critical section nesting:
.. [] debug_smp_processor_id+0x56/0xb8
.[] .. ( <= nf_conntrack_in+0x43d/0x468 [nf_conntrack])
l *0xc0218336
0xc0218336 is in debug_smp_processor_id (lib/smp_processor_id.c:42).
37 /*
38 * Avoid recursion:
39 */
40 preempt_disable();
41
42 if (!printk_ratelimit())
43 goto out_enable;
44
45 printk(KERN_ERR "BUG: using smp_processor_id() in preemptible
[%08x] code: %s/%d\n", preempt_count()-1, current->comm, current->pid);
46 print_symbol("caller is %s\n",
(long)__builtin_return_address(0));
http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc5-rt4/rt-dmesg2
Regards,
Michal
--
Michal K. K. Piotrowski
LTG - Linux Testers Group (PL)
(http://www.stardust.webpages.pl/ltg/)
LTG - Linux Testers Group (EN)
(http://www.stardust.webpages.pl/linux_testers_group_en/)
-
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/
2.6.21-rc5-rt4 inconsistent lock state
Hi,
artsd during kde start triggered this
=
[ INFO: inconsistent lock state ]
[ 2.6.21-rc5-rt4 #4
-
inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
artsd/3454 [HC1[1]:SC0[0]:HE0:SE1] takes:
((raw_spinlock_t *)(>wait_lock)){+-..}, at: []
rt_spin_lock_slowlock+0x29/0x1b4
{hardirq-on-W} state was registered at:
[] mark_lock+0x73/0x4a9
[] mark_held_locks+0x52/0x6f
[] trace_hardirqs_on+0x116/0x162
[] __spin_unlock_irqrestore+0x54/0x70
[] task_blocks_on_rt_mutex+0x1d6/0x226
[] rt_spin_lock_slowlock+0xcf/0x1b4
[] rt_spin_lock+0x13/0x4b
[] wait_for_completion+0x2e/0xab
[] set_cpus_allowed+0x88/0xab
[] measure_one+0xab/0x184
[] build_sched_domains+0x5b1/0xc19
[] arch_init_sched_domains+0x25/0x27
[] sched_init_smp+0x1c/0x6a
[] init+0x121/0x361
[] kernel_thread_helper+0x7/0x10
[] 0x
irq event stamp: 116668
hardirqs last enabled at (116667): []
__spin_unlock_irqrestore+0x54/0x70
hardirqs last disabled at (116668): [] apic_timer_interrupt+0x29/0x38
softirqs last enabled at (0): [] copy_process+0x542/0x1440
softirqs last disabled at (0): [<>] 0x0
l *0xc0358d1f
0xc0358d1f is in rt_spin_lock_slowlock (kernel/rtmutex.c:640).
635 unsigned long saved_state, state, flags;
636
637 debug_rt_mutex_init_waiter();
638 waiter.task = NULL;
639
640 spin_lock_irqsave(>wait_lock, flags);
641 init_lists(lock);
642
643 /* Try to acquire the lock again: */
644 if (try_to_take_rt_mutex(lock)) {
l *0xc035a616
0xc035a616 is in __spin_unlock_irqrestore (include/asm/irqflags.h:33).
28 return flags;
29 }
30
31 static inline void raw_local_irq_restore(unsigned long flags)
32 {
33 __asm__ __volatile__(
34 "pushl %0 ; popfl"
35 : /* no output */
36 :"g" (flags)
37 :"memory", "cc"
l *0xc0104de9
0xc0104de9 is at include/asm/bitops.h:246.
241 static int test_bit(int nr, const volatile void * addr);
242 #endif
243
244 static __always_inline int constant_test_bit(int nr, const volatile
unsigned long *addr)
245 {
246 return ((1UL << (nr & 31)) & (addr[nr >> 5])) != 0;
247 }
248
249 static inline int variable_test_bit(int nr, const volatile unsigned
long * addr)
250 {
l *0xc0123b51
0xc0123b51 is in copy_process (kernel/fork.c:1129).
1124p->hardirq_enable_ip = 0;
1125p->hardirq_enable_event = 0;
1126p->hardirq_disable_ip = _THIS_IP_;
1127p->hardirq_disable_event = 0;
1128p->softirqs_enabled = 1;
1129p->softirq_enable_ip = _THIS_IP_;
1130p->softirq_enable_event = 0;
1131p->softirq_disable_ip = 0;
1132p->softirq_disable_event = 0;
1133p->hardirq_context = 0;
other info that might help us debug this:
1 lock held by artsd/3454:
#0: (>tread_sem){--..}, at: [] snd_timer_user_ioctl+0x618/0xb0d
[snd_timer]
stack backtrace:
[] dump_trace+0x78/0x21a
[] show_trace_log_lvl+0x35/0x54
[] show_trace+0x2c/0x2e
[] dump_stack+0x29/0x2b
[] print_usage_bug+0x14d/0x157
[] mark_lock+0xb0/0x4a9
[] __lock_acquire+0x3cf/0xc36
[] lock_acquire+0x6e/0x86
[] __spin_lock_irqsave+0x55/0x65
[] rt_spin_lock_slowlock+0x29/0x1b4
[] rt_spin_lock+0x13/0x4b
[] serial8250_console_write+0x4e/0x155
[] __call_console_drivers+0x73/0x88
[] _call_console_drivers+0x74/0x7a
[] release_console_sem+0x11e/0x1ad
[] vprintk+0x2dc/0x32b
[] printk+0x20/0x22
[] task_running_tick+0x401/0x450
[] scheduler_tick+0x188/0x1e3
[] update_process_times+0x40/0x6d
[] tick_sched_timer+0x76/0xb6
[] hrtimer_interrupt+0x15d/0x205
[] smp_apic_timer_interrupt+0x94/0xa7
[] apic_timer_interrupt+0x33/0x38
[] __spin_unlock_irqrestore+0x56/0x70
[] rt_mutex_adjust_prio+0x31/0x37
[] rt_spin_lock_slowunlock+0x6d/0x73
[] rt_spin_unlock+0x2f/0x35
[] kfree+0x9d/0xa5
[] snd_timer_user_ioctl+0x6c1/0xb0d [snd_timer]
[] do_ioctl+0x32/0x7f
[] vfs_ioctl+0x291/0x2a4
[] sys_ioctl+0x60/0x79
[] syscall_call+0x7/0xb
[] 0xb7f28410
===
---
| preempt count: 00010001 ]
| 1-level deep critical section nesting:
.. [] __spin_lock_irqsave+0x23/0x65
.[] .. ( <= rt_spin_lock_slowlock+0x29/0x1b4)
l *0xc035a0da
0xc035a0da is in __spin_lock_irqsave (kernel/spinlock.c:122).
117 {
118 unsigned long flags;
119
120 local_irq_save(flags);
121 preempt_disable();
122 spin_acquire(>dep_map, 0, 0, _RET_IP_);
123 /*
124 * On lockdep we dont want the hand-coded irq-enable of
125 * _raw_spin_lock_flags() code, because lockdep assumes
126 * that interrupts are not re-enabled during lock-acquire:
l *0xc0358d1f
0xc0358d1f is in
2.6.21-rc5-rt4 inconsistent lock state
Hi,
artsd during kde start triggered this
=
[ INFO: inconsistent lock state ]
[ 2.6.21-rc5-rt4 #4
-
inconsistent {hardirq-on-W} - {in-hardirq-W} usage.
artsd/3454 [HC1[1]:SC0[0]:HE0:SE1] takes:
((raw_spinlock_t *)(lock-wait_lock)){+-..}, at: [c0358d1f]
rt_spin_lock_slowlock+0x29/0x1b4
{hardirq-on-W} state was registered at:
[c0143a91] mark_lock+0x73/0x4a9
[c0143f19] mark_held_locks+0x52/0x6f
[c0144115] trace_hardirqs_on+0x116/0x162
[c035a616] __spin_unlock_irqrestore+0x54/0x70
[c014a2a4] task_blocks_on_rt_mutex+0x1d6/0x226
[c0358dc5] rt_spin_lock_slowlock+0xcf/0x1b4
[c035959b] rt_spin_lock+0x13/0x4b
[c035804f] wait_for_completion+0x2e/0xab
[c012048d] set_cpus_allowed+0x88/0xab
[c012055b] measure_one+0xab/0x184
[c0120be5] build_sched_domains+0x5b1/0xc19
[c0121272] arch_init_sched_domains+0x25/0x27
[c04dccec] sched_init_smp+0x1c/0x6a
[c04d0590] init+0x121/0x361
[c0104ff7] kernel_thread_helper+0x7/0x10
[] 0x
irq event stamp: 116668
hardirqs last enabled at (116667): [c035a616]
__spin_unlock_irqrestore+0x54/0x70
hardirqs last disabled at (116668): [c0104de9] apic_timer_interrupt+0x29/0x38
softirqs last enabled at (0): [c0123b51] copy_process+0x542/0x1440
softirqs last disabled at (0): [] 0x0
l *0xc0358d1f
0xc0358d1f is in rt_spin_lock_slowlock (kernel/rtmutex.c:640).
635 unsigned long saved_state, state, flags;
636
637 debug_rt_mutex_init_waiter(waiter);
638 waiter.task = NULL;
639
640 spin_lock_irqsave(lock-wait_lock, flags);
641 init_lists(lock);
642
643 /* Try to acquire the lock again: */
644 if (try_to_take_rt_mutex(lock)) {
l *0xc035a616
0xc035a616 is in __spin_unlock_irqrestore (include/asm/irqflags.h:33).
28 return flags;
29 }
30
31 static inline void raw_local_irq_restore(unsigned long flags)
32 {
33 __asm__ __volatile__(
34 pushl %0 ; popfl
35 : /* no output */
36 :g (flags)
37 :memory, cc
l *0xc0104de9
0xc0104de9 is at include/asm/bitops.h:246.
241 static int test_bit(int nr, const volatile void * addr);
242 #endif
243
244 static __always_inline int constant_test_bit(int nr, const volatile
unsigned long *addr)
245 {
246 return ((1UL (nr 31)) (addr[nr 5])) != 0;
247 }
248
249 static inline int variable_test_bit(int nr, const volatile unsigned
long * addr)
250 {
l *0xc0123b51
0xc0123b51 is in copy_process (kernel/fork.c:1129).
1124p-hardirq_enable_ip = 0;
1125p-hardirq_enable_event = 0;
1126p-hardirq_disable_ip = _THIS_IP_;
1127p-hardirq_disable_event = 0;
1128p-softirqs_enabled = 1;
1129p-softirq_enable_ip = _THIS_IP_;
1130p-softirq_enable_event = 0;
1131p-softirq_disable_ip = 0;
1132p-softirq_disable_event = 0;
1133p-hardirq_context = 0;
other info that might help us debug this:
1 lock held by artsd/3454:
#0: (tu-tread_sem){--..}, at: [f98abe00] snd_timer_user_ioctl+0x618/0xb0d
[snd_timer]
stack backtrace:
[c0105470] dump_trace+0x78/0x21a
[c0105647] show_trace_log_lvl+0x35/0x54
[c0105dcc] show_trace+0x2c/0x2e
[c0105e93] dump_stack+0x29/0x2b
[c014320b] print_usage_bug+0x14d/0x157
[c0143ace] mark_lock+0xb0/0x4a9
[c014498c] __lock_acquire+0x3cf/0xc36
[c0145261] lock_acquire+0x6e/0x86
[c035a10c] __spin_lock_irqsave+0x55/0x65
[c0358d1f] rt_spin_lock_slowlock+0x29/0x1b4
[c035959b] rt_spin_lock+0x13/0x4b
[c0276d47] serial8250_console_write+0x4e/0x155
[c0125c2f] __call_console_drivers+0x73/0x88
[c0125cb8] _call_console_drivers+0x74/0x7a
[c0125f4e] release_console_sem+0x11e/0x1ad
[c0126644] vprintk+0x2dc/0x32b
[c01266b3] printk+0x20/0x22
[c011e39d] task_running_tick+0x401/0x450
[c012180f] scheduler_tick+0x188/0x1e3
[c012f964] update_process_times+0x40/0x6d
[c01416c7] tick_sched_timer+0x76/0xb6
[c013d5b6] hrtimer_interrupt+0x15d/0x205
[c01161c5] smp_apic_timer_interrupt+0x94/0xa7
[c0104df3] apic_timer_interrupt+0x33/0x38
[c035a618] __spin_unlock_irqrestore+0x56/0x70
[c014a325] rt_mutex_adjust_prio+0x31/0x37
[c0358c36] rt_spin_lock_slowunlock+0x6d/0x73
[c0359602] rt_spin_unlock+0x2f/0x35
[c0182d71] kfree+0x9d/0xa5
[f98abea9] snd_timer_user_ioctl+0x6c1/0xb0d [snd_timer]
[c0193d5e] do_ioctl+0x32/0x7f
[c019403c] vfs_ioctl+0x291/0x2a4
[c01940af] sys_ioctl+0x60/0x79
[c010432d] syscall_call+0x7/0xb
[b7f28410] 0xb7f28410
===
---
| preempt count: 00010001 ]
| 1-level deep critical section nesting:
.. [c035a0da] __spin_lock_irqsave+0x23/0x65
.[c0358d1f] .. ( = rt_spin_lock_slowlock+0x29/0x1b4)
l *0xc035a0da
0xc035a0da is in __spin_lock_irqsave (kernel/spinlock.c:122).
117 {
118
Re: 2.6.21-rc5-rt4 inconsistent lock state
Michal Piotrowski napisał(a):
Hi,
[..]
http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc5-rt4/rt-config
http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc5-rt4/rt-dmesg
I just fixed an isic build in AT :)
BUG: isic:11396 task might have lost a preemption check!
[c0105470] dump_trace+0x78/0x21a
[c0105647] show_trace_log_lvl+0x35/0x54
[c0105dcc] show_trace+0x2c/0x2e
[c0105e93] dump_stack+0x29/0x2b
[c0121d64] preempt_enable_no_resched+0x5c/0x5e
[c0218390] debug_smp_processor_id+0xb0/0xb8
[fd98a83f] nf_conntrack_in+0x39c/0x468 [nf_conntrack]
[fd999316] ipv4_conntrack_local+0x61/0x67 [nf_conntrack_ipv4]
[c031c494] nf_iterate+0x40/0x71
[c031c61a] nf_hook_slow+0x5c/0xd7
[c033f066] raw_sendmsg+0x518/0x6ee
[c0346819] inet_sendmsg+0x4b/0x55
[c030109b] sock_sendmsg+0xf7/0x114
[c0301b34] sys_sendto+0xe5/0x105
[c0302521] sys_socketcall+0x17e/0x254
[c010432d] syscall_call+0x7/0xb
[b7f0c410] 0xb7f0c410
===
---
| preempt count: ]
| 0-level deep critical section nesting:
BUG: using smp_processor_id() in preemptible [] code: isic/16471
caller is nf_conntrack_in+0xd0/0x468 [nf_conntrack]
[c0105470] dump_trace+0x78/0x21a
[c0105647] show_trace_log_lvl+0x35/0x54
[c0105dcc] show_trace+0x2c/0x2e
[c0105e93] dump_stack+0x29/0x2b
[c021838b] debug_smp_processor_id+0xab/0xb8
[fd98a573] nf_conntrack_in+0xd0/0x468 [nf_conntrack]
[fd999316] ipv4_conntrack_local+0x61/0x67 [nf_conntrack_ipv4]
[c031c494] nf_iterate+0x40/0x71
[c031c61a] nf_hook_slow+0x5c/0xd7
[c033f066] raw_sendmsg+0x518/0x6ee
[c0346819] inet_sendmsg+0x4b/0x55
[c030109b] sock_sendmsg+0xf7/0x114
[c0301b34] sys_sendto+0xe5/0x105
[c0302521] sys_socketcall+0x17e/0x254
[c010432d] syscall_call+0x7/0xb
[b7f01410] 0xb7f01410
===
---
| preempt count: 0001 ]
| 1-level deep critical section nesting:
.. [c0359d9e] __spin_lock+0x1a/0x59
.[c016321a] .. ( = handle_fasteoi_irq+0x27/0xdf)
l *0xc0359d9e
0xc0359d9e is in __spin_lock (kernel/spinlock.c:218).
213 EXPORT_SYMBOL(__write_lock_bh);
214
215 void __lockfunc __spin_lock(raw_spinlock_t *lock)
216 {
217 preempt_disable();
218 spin_acquire(lock-dep_map, 0, 0, _RET_IP_);
219 _raw_spin_lock(lock);
220 }
221
222 EXPORT_SYMBOL(__spin_lock);
l *0xc016321a
0xc016321a is in handle_fasteoi_irq (kernel/irq/chip.c:405).
400 struct irqaction *action;
401 irqreturn_t action_ret;
402
403 spin_lock(desc-lock);
404
405 if (unlikely(desc-status IRQ_INPROGRESS))
406 goto out;
407
408 desc-status = ~(IRQ_REPLAY | IRQ_WAITING);
409 kstat_cpu(cpu).irqs[irq]++;
BUG: using smp_processor_id() in preemptible [] code: isic/16471
caller is nf_conntrack_in+0x43d/0x468 [nf_conntrack]
[c0105470] dump_trace+0x78/0x21a
[c0105647] show_trace_log_lvl+0x35/0x54
[c0105dcc] show_trace+0x2c/0x2e
[c0105e93] dump_stack+0x29/0x2b
[c021838b] debug_smp_processor_id+0xab/0xb8
[fd98a8e0] nf_conntrack_in+0x43d/0x468 [nf_conntrack]
[fd999316] ipv4_conntrack_local+0x61/0x67 [nf_conntrack_ipv4]
[c031c494] nf_iterate+0x40/0x71
[c031c61a] nf_hook_slow+0x5c/0xd7
[c033f066] raw_sendmsg+0x518/0x6ee
[c0346819] inet_sendmsg+0x4b/0x55
[c030109b] sock_sendmsg+0xf7/0x114
[c0301b34] sys_sendto+0xe5/0x105
[c0302521] sys_socketcall+0x17e/0x254
[c010432d] syscall_call+0x7/0xb
[b7f01410] 0xb7f01410
===
---
| preempt count: 0001 ]
| 1-level deep critical section nesting:
.. [c0218336] debug_smp_processor_id+0x56/0xb8
.[fd98a8e0] .. ( = nf_conntrack_in+0x43d/0x468 [nf_conntrack])
l *0xc0218336
0xc0218336 is in debug_smp_processor_id (lib/smp_processor_id.c:42).
37 /*
38 * Avoid recursion:
39 */
40 preempt_disable();
41
42 if (!printk_ratelimit())
43 goto out_enable;
44
45 printk(KERN_ERR BUG: using smp_processor_id() in preemptible
[%08x] code: %s/%d\n, preempt_count()-1, current-comm, current-pid);
46 print_symbol(caller is %s\n,
(long)__builtin_return_address(0));
http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc5-rt4/rt-dmesg2
Regards,
Michal
--
Michal K. K. Piotrowski
LTG - Linux Testers Group (PL)
(http://www.stardust.webpages.pl/ltg/)
LTG - Linux Testers Group (EN)
(http://www.stardust.webpages.pl/linux_testers_group_en/)
-
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/
