Re: 2.6.20-git15 BUG: soft lockup detected on CPU#0! - timers?

From: Michal Piotrowski
Date: Thu Feb 22 2007 - 05:51:09 EST

Next message: Duncan Sands: "Re: [PATCH 2/2] usbatm: Detect usb device shutdown and ignore failed urbs."
Previous message: Pekka Enberg: "Re: SLUB: The unqueued Slab allocator"
In reply to: Michal Piotrowski: "Re: 2.6.20-git15 BUG: soft lockup detected on CPU#0! - timers?"
Next in thread: Ingo Molnar: "Re: 2.6.20-git15 BUG: soft lockup detected on CPU#0! - timers?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Michal Piotrowski napisał(a):
> Thomas Gleixner napisał(a):
>> Michal,
>>
>> On Wed, 2007-02-21 at 16:38 +0100, Michal Piotrowski wrote:
>>>> But you still have those softirq pending messages, right ?
>>> Yes
>>>
>>> (+ new NOHZ: local_softirq_pending 02)
>> Yike, that's the timer softirq.
>>
>> Can you add the patch below, maybe it gives us some useful info. Please
>> enable lockdep (your last config had it already)
>>
>
> I hope this helps.
>
> irq event stamp: 103630856
> hardirqs last enabled at (103630855): [<c031356a>] _spin_unlock_irq+0x22/0x43
> hardirqs last disabled at (103630856): [<c013a00e>] tick_nohz_stop_sched_tick+0x13/0x1fd
> softirqs last enabled at (103630824): [<c01265df>] __do_softirq+0xe4/0xea
> softirqs last disabled at (103630819): [<c0106a75>] do_softirq+0x64/0xd1
> NOHZ: local_softirq_pending 20, 00000001
>
> (gdb) l *0xc031356a
> 0xc031356a is in _spin_unlock_irq (include2/asm/irqflags.h:48).
> 43 __asm__ __volatile__("cli" : : : "memory");
> 44 }
> 45
> 46 static inline void raw_local_irq_enable(void)
> 47 {
> 48 __asm__ __volatile__("sti" : : : "memory");
> 49 }
> 50
> 51 /*
> 52 * Used in the idle loop; sti takes one instruction cycle
> (gdb) l *0xc013a00e
> 0xc013a00e is in tick_nohz_stop_sched_tick (/mnt/md0/devel/linux-git/kernel/time/tick-sched.c:158).
> 153 ktime_t last_update, expires, now, delta;
> 154 int cpu;
> 155
> 156 local_irq_save(flags);
> 157
> 158 cpu = smp_processor_id();
> 159 ts = &per_cpu(tick_cpu_sched, cpu);
> 160
> 161 if (unlikely(ts->nohz_mode == NOHZ_MODE_INACTIVE))
> 162 goto end;
> (gdb) l *0xc01265df
> 0xc01265df is in __do_softirq (/mnt/md0/devel/linux-git/kernel/softirq.c:251).
> 246
> 247 trace_softirq_exit();
> 248
> 249 account_system_vtime(current);
> 250 _local_bh_enable();
> 251 }
> 252
> 253 #ifndef __ARCH_HAS_DO_SOFTIRQ
> 254
> 255 asmlinkage void do_softirq(void)
> (gdb) l *0xc0106a75
> 0xc0106a75 is in do_softirq (/mnt/md0/devel/linux-git/arch/i386/kernel/irq.c:222).
> 217 irqctx->tinfo.previous_esp = current_stack_pointer;
> 218
> 219 /* build the stack frame on the softirq stack */
> 220 isp = (u32*) ((char*)irqctx + sizeof(*irqctx));
> 221
> 222 asm volatile(
> 223 " xchgl %%ebx,%%esp \n"
> 224 " call __do_softirq \n"
> 225 " movl %%ebx,%%esp \n"
> 226 : "=b"(isp)
>

Here is more

BUG: at /mnt/md0/devel/linux-git/kernel/lockdep.c:2427 check_flags()
[<c01050f9>] show_trace_log_lvl+0x1a/0x2f
[<c01057e0>] show_trace+0x12/0x14
[<c0105892>] dump_stack+0x16/0x18
[<c013abf7>] check_flags+0x95/0x143
[<c013d978>] lock_acquire+0x29/0x82
[<c0136974>] down_write+0x3a/0x54
[<c01630f8>] sys_munmap+0x23/0x3f
[<c0104120>] syscall_call+0x7/0xb
=======================
irq event stamp: 30788
hardirqs last enabled at (30787): [<c0104249>] syscall_exit_work+0x11/0x26
hardirqs last disabled at (30788): [<c0103fc9>] ret_from_exception+0x9/0xc
softirqs last enabled at (30202): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (30193): [<c0106a75>] do_softirq+0x64/0xd1
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 24, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 24, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 02, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 06, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 24, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 02, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 06, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 02, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 06, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 06, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 06, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 24, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 24, 00000001
irq event stamp: 137191105
hardirqs last enabled at (137191105): [<c0102b80>] default_idle+0x3e/0x59
hardirqs last disabled at (137191104): [<c0102451>] cpu_idle+0xba/0xfb
softirqs last enabled at (137190592): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (137190587): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 20, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 24, 00000001
irq event stamp: 214661966
hardirqs last enabled at (214661965): [<c0104168>] restore_nocheck+0x12/0x15
hardirqs last disabled at (214661966): [<c0313174>] _spin_lock_irq+0xf/0x48
softirqs last enabled at (214661782): [<c01265df>] __do_softirq+0xe4/0xea
softirqs last disabled at (214661755): [<c0106a75>] do_softirq+0x64/0xd1
NOHZ: local_softirq_pending 06, 00000001

http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc1/git-config
http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc1/git-dmesg2

[<c01265df>] __do_softirq+0xe4/0xea
[<c0106a75>] do_softirq+0x64/0xd1

this repeats every time

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 majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Duncan Sands: "Re: [PATCH 2/2] usbatm: Detect usb device shutdown and ignore failed urbs."
Previous message: Pekka Enberg: "Re: SLUB: The unqueued Slab allocator"
In reply to: Michal Piotrowski: "Re: 2.6.20-git15 BUG: soft lockup detected on CPU#0! - timers?"
Next in thread: Ingo Molnar: "Re: 2.6.20-git15 BUG: soft lockup detected on CPU#0! - timers?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]