Re: 2.6.14-rc5-rt6 -- False NMI lockup detects

[George Anzinger <george@mvista.com>]

Steven Rostedt wrote:
> On Tue, 2005-10-25 at 16:28 +0200, Ingo Molnar wrote:
> 
>>* Steven Rostedt <rostedt@goodmis.org> wrote:
>>
>>
>>>Hi Ingo and Thomas,
>>>
>>>On some of my machines, I've been experiencing false NMI lockups.  
>>>This usually happens on slower machines, and taking a look into this, 
>>>it seems to be due to a short time where no processes are using 
>>>timers, and the ktimer interrupts aren't needed. So the APIC timer, 
>>>which now is used only for the ktimers, has a five second pause, and 
>>>causes the NMI to go off.  The NMI uses the apic timer to determine 
>>>lockups.
>>
>>this would be a bug - the jiffy tick should be processed every 1 msec, 
>>regardless of whether there are any ktimers pending. (in the future we 
>>want to use a special ktimer for the jiffy tick, but that's not 
>>implemented yet.)
>>
> 
> 
> Isn't the jiffy tick implemented with the PIT when possible? So the apic
> is only used when a timer is needed.  Also note that this "lockup"
> happens on boot up while things are being initialized, so not many
> things may be using the timer.

Somewhere in the not too distant past the NMI watchdog was moved from the PIT tick to the APIC 
timer.  Might want to move it back, at least for now...
> 
> Also, the machine doesn't lock up.  It continues happily along at normal
> speed.  It's only a 366 MHz machine.
> 
> At my customer's site (which I'm no longer at), my test machine (2GHz)
> never showed this, but an equal machine that my customer had showed this
> on every boot up.  The only difference between the two machines was the
> other one had a 1GHz processor. These were both running on modified -rt
> kernels.
> 
> 
> 
>>>So, I added a more generic method. This only works for x86 for now, 
>>>but it has a #ifdef to keep other archs working until it implements 
>>>this as well.  I added a nmi_irq_incr which is called by __do_IRQ in 
>>>the generic code.  This is what is used in the NMI code to determine 
>>>if the CPU has locked up.  This way we don't have to worry about what 
>>>resource we are using for timers.
>>
>>this will be useful for tickless stuff - but right now 'no APIC timer 
>>irq for 5 seconds' is a 'must not happen'.
>>
> 
> 
> I added the following patch:
> 
> Index: rt_linux_ernie/arch/i386/kernel/nmi.c
> ===================================================================
> --- rt_linux_ernie.orig/arch/i386/kernel/nmi.c	2005-10-25 12:58:18.000000000 -0400
> +++ rt_linux_ernie/arch/i386/kernel/nmi.c	2005-10-25 14:52:38.000000000 -0400
> @@ -538,6 +538,8 @@
>  		 * wait a few IRQs (5 seconds) before doing the oops ...
>  		 */
>  		alert_counter[cpu]++;
> +		if (alert_counter[cpu] && !(alert_counter[cpu] % (nmi_hz)))
> +			early_printk("nmi: jiffies=%ld\n",jiffies);
>  		if (alert_counter[cpu] && !(alert_counter[cpu] % (5*nmi_hz))) {
>  			int i;
>  
> 
> And this is my output:
> 
> Adding 554200k swap on /dev/hda5.  Priority:-1 extents:1 across:554200k
> EXT3 FS on hda1, internal journal
> nmi: jiffies=-289143
> nmi: jiffies=-272171
> nmi: jiffies=-270269
> nmi: jiffies=-268754
> nmi: jiffies=-267630
> NMI watchdog detected lockup on CPU#0 (50000/50000)
> 
> 
>>>>>my comments
> 
> 
> The above shows that the jiffies are incrementing. So what reason would
> the apic timer be going off?  Also, this is just a UP machine.
> 
> <<<< end my comments
> 
> Pid: 1378, comm:                uname
> EIP: 0060:[<c01f5592>] CPU: 0
> EIP is at clear_user+0x32/0x50
>  EFLAGS: 00010202    Not tainted  (2.6.14-rc5-rt6)
> EAX: 00000000 EBX: 00000000 ECX: 0000009c EDX: 00000000
> ESI: fffffff2 EDI: b7f10d90 EBP: cf055e28 DS: 007b ES: 007b
> CR0: 8005003b CR2: b7f10750 CR3: 0f7d8000 CR4: 00000690
>  [<c01010ba>] show_regs+0x14a/0x174 (36)
>  [<c010ff13>] nmi_watchdog_tick+0x1a3/0x230 (56)
>  [<c0104b2b>] default_do_nmi+0x6b/0x160 (52)
>  [<c0104c5a>] do_nmi+0x2a/0x30 (20)
>  [<c0103a46>] nmi_stack_correct+0x1d/0x22 (68)
>  [<c018e813>] padzero+0x33/0x40 (16)
>  [<c018eecd>] load_elf_interp+0x22d/0x2e0 (72)
>  [<c018fca5>] load_elf_binary+0xb85/0xd30 (188)
>  [<c016d70a>] search_binary_handler+0xaa/0x2b0 (44)
>  [<c016da99>] do_execve+0x189/0x230 (36)
>  [<c0101a92>] sys_execve+0x42/0xa0 (40)
>  [<c0102f01>] syscall_call+0x7/0xb (-8116)
> NMI Watchdog detected LOCKUP on CPU0, eip c01f5592, registers:
> Modules linked in:
> CPU:    0
> EIP:    0060:[<c01f5592>]    Not tainted VLI
> EFLAGS: 00010202   (2.6.14-rc5-rt6)
> EIP is at clear_user+0x32/0x50
> eax: 00000000   ebx: 00000000   ecx: 0000009c   edx: 00000000
> esi: fffffff2   edi: b7f10d90   ebp: cf055e28   esp: cf055e20
> ds: 007b   es: 007b   ss: 0068   preempt: 00000001
> Process uname (pid: 1378, threadinfo=cf054000 task=cfed9150 stack_left=7660 wor)Stack: cfc25120 cfc25594 cf055e38 c018e813 b7f10750 000008b0 cf055e80 c018eecd
>        b7f10750 b7f0fcc0 cfc25080 00000003 00000812 00015cc0 cfc25060 b7efa000
>        00000001 b7f107f8 00000006 cfc25088 b7f10750 cfc25560 0804b2ec cec5d720
> Call Trace:
>  [<c0103d3b>] show_stack+0xab/0xf0 (28)
>  [<c0103f1a>] show_registers+0x17a/0x230 (56)
>  [<c0104a6e>] die_nmi+0x9e/0xf0 (52)
>  [<c010ff37>] nmi_watchdog_tick+0x1c7/0x230 (56)
>  [<c0104b2b>] default_do_nmi+0x6b/0x160 (52)
>  [<c0104c5a>] do_nmi+0x2a/0x30 (20)
>  [<c0103a46>] nmi_stack_correct+0x1d/0x22 (68)
>  [<c018e813>] padzero+0x33/0x40 (16)
>  [<c018eecd>] load_elf_interp+0x22d/0x2e0 (72)
>  [<c018fca5>] load_elf_binary+0xb85/0xd30 (188)
>  [<c016d70a>] search_binary_handler+0xaa/0x2b0 (44)
>  [<c016da99>] do_execve+0x189/0x230 (36)
>  [<c0101a92>] sys_execve+0x42/0xa0 (40)
>  [<c0102f01>] syscall_call+0x7/0xb (-8116)
> Code: 7c 24 04 8b 7d 08 89 1c 24 8b 4d 0c a1 48 e4 33 c0 89 fb 01 cb 19 d2 39 5
> console shuts up ...
> 
> -- Steve
> 
> 
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 

-- 
George Anzinger   george@mvista.com
HRT (High-res-timers):  http://sourceforge.net/projects/high-res-timers/