Hello,
I'm experiencing a full system lockup. I'm using an out-of-tree driver
which I suspect is responsible. I'm trying to enable the NMI watchdog.
# cat /proc/version
Linux version 2.6.22.1-rt9 (gcc version 3.4.6) #1 PREEMPT RT Tue Oct 9
12:25:47 CEST 2007
# cat /proc/cmdline
ro root=/dev/hdc1 console=ttyS0,57600n8 console=tty0 panic=3 apic=debug
nmi_watchdog=2
However, after boot, the NMI count does not change.
# cat /proc/interrupts ; sleep 10 ; cat /proc/interrupts
CPU0
0: 99 IO-APIC-edge timer
4: 3822 IO-APIC-edge serial
8: 1 IO-APIC-edge rtc
9: 0 IO-APIC-fasteoi acpi
15: 16443 IO-APIC-edge ide1
16: 2166 IO-APIC-fasteoi eth0
17: 840 IO-APIC-fasteoi eth1
18: 840 IO-APIC-fasteoi eth2
19: 840 IO-APIC-fasteoi eth3
20: 0 IO-APIC-fasteoi Dta1xx
21: 0 IO-APIC-fasteoi Dta1xx
NMI: 2895
LOC: 168445
ERR: 0
MIS: 0
CPU0
0: 99 IO-APIC-edge timer
4: 3822 IO-APIC-edge serial
8: 1 IO-APIC-edge rtc
9: 0 IO-APIC-fasteoi acpi
15: 16467 IO-APIC-edge ide1
16: 2173 IO-APIC-fasteoi eth0
17: 845 IO-APIC-fasteoi eth1
18: 845 IO-APIC-fasteoi eth2
19: 845 IO-APIC-fasteoi eth3
20: 0 IO-APIC-fasteoi Dta1xx
21: 0 IO-APIC-fasteoi Dta1xx
NMI: 2895
LOC: 169448
ERR: 0
MIS: 0
Does this mean the NMI watchdog is not working correctly on my system?
# dmesg | grep NMI
ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
Testing NMI watchdog ... OK.
Regards.
On 2007.10.12 11:18:24 +0200, John Sigler wrote:
> Hello,
>
> I'm experiencing a full system lockup. I'm using an out-of-tree driver
> which I suspect is responsible. I'm trying to enable the NMI watchdog.
>
> # cat /proc/version
> Linux version 2.6.22.1-rt9 (gcc version 3.4.6) #1 PREEMPT RT Tue Oct 9
> 12:25:47 CEST 2007
>
> # cat /proc/cmdline
> ro root=/dev/hdc1 console=ttyS0,57600n8 console=tty0 panic=3 apic=debug
> nmi_watchdog=2
>
> However, after boot, the NMI count does not change.
>
> # cat /proc/interrupts ; sleep 10 ; cat /proc/interrupts
Try running some cpu hog in the background. The performance counters get
increased only when the CPU is actually doing something. On a mostly
idle system, it can take quite a while for the next NMI to show up.
Bj?rn
--
On Fri, 12 Oct 2007, John Sigler wrote:
> Hello,
>
> I'm experiencing a full system lockup. I'm using an out-of-tree driver
> which I suspect is responsible. I'm trying to enable the NMI watchdog.
>
> # cat /proc/version
> Linux version 2.6.22.1-rt9 (gcc version 3.4.6) #1 PREEMPT RT Tue Oct 9
> 12:25:47 CEST 2007
>
> # cat /proc/cmdline
> ro root=/dev/hdc1 console=ttyS0,57600n8 console=tty0 panic=3 apic=debug
> nmi_watchdog=2
>
I've noticed on some boxes that nmi_watchdog=2 does what you state. Try
out nmi_watchdog=1.
-- Steve
Bj?rn Steinbrink wrote:
> John Sigler wrote:
>
>> I'm experiencing a full system lockup. I'm using an out-of-tree driver
>> which I suspect is responsible. I'm trying to enable the NMI watchdog.
>>
>> # cat /proc/version
>> Linux version 2.6.22.1-rt9 (gcc version 3.4.6) #1 PREEMPT RT Tue Oct 9
>> 12:25:47 CEST 2007
>>
>> # cat /proc/cmdline
>> ro root=/dev/hdc1 console=ttyS0,57600n8 console=tty0 panic=3 apic=debug
>> nmi_watchdog=2
>>
>> However, after boot, the NMI count does not change.
>>
>> # cat /proc/interrupts ; sleep 10 ; cat /proc/interrupts
>
> Try running some cpu hog in the background. The performance counters get
> increased only when the CPU is actually doing something. On a mostly
> idle system, it can take quite a while for the next NMI to show up.
You are right. In another shell, I ran while true; do : ; done
# cat /proc/interrupts ; sleep 10 ; cat /proc/interrupts
CPU0
0: 100 IO-APIC-edge timer
4: 82 IO-APIC-edge serial
8: 1 IO-APIC-edge rtc
9: 0 IO-APIC-fasteoi acpi
15: 13648 IO-APIC-edge ide1
16: 1303 IO-APIC-fasteoi eth0
17: 575 IO-APIC-fasteoi eth1
18: 575 IO-APIC-fasteoi eth2
19: 575 IO-APIC-fasteoi eth3
NMI: 2889
LOC: 115768
ERR: 0
MIS: 0
CPU0
0: 100 IO-APIC-edge timer
4: 82 IO-APIC-edge serial
8: 1 IO-APIC-edge rtc
9: 0 IO-APIC-fasteoi acpi
15: 13672 IO-APIC-edge ide1
16: 1310 IO-APIC-fasteoi eth0
17: 580 IO-APIC-fasteoi eth1
18: 580 IO-APIC-fasteoi eth2
19: 580 IO-APIC-fasteoi eth3
NMI: 2899
LOC: 116770
ERR: 0
MIS: 0
The performance counter appears to be configured to fire when the event
count for CPU_CLK_UNHALTED reaches 2,400,000,000 (I have a 2.4 GHz CPU)
i.e. one NMI per second when the CPU is 100% busy. Is that correct?
On a related note, I have a Pentium 3 which counts CPU_CLK_UNHALTED
cycles even when the CPU is halted. I was told this is a bug, but it
actually sounds like a a nice feature!
Is there really no way to have the event counter increment with every
tick (even when the CPU is halted) on a P4?
Regards.
Steven Rostedt wrote:
> John Sigler wrote:
>
>> I'm experiencing a full system lockup. I'm using an out-of-tree driver
>> which I suspect is responsible. I'm trying to enable the NMI watchdog.
>>
>> # cat /proc/version
>> Linux version 2.6.22.1-rt9 (gcc version 3.4.6) #1 PREEMPT RT Tue Oct 9
>> 12:25:47 CEST 2007
>>
>> # cat /proc/cmdline
>> ro root=/dev/hdc1 console=ttyS0,57600n8 console=tty0 panic=3 apic=debug
>> nmi_watchdog=2
>
> I've noticed on some boxes that nmi_watchdog=2 does what you state. Try
> out nmi_watchdog=1.
# diff boot_message013 boot_message014
49c49
< Kernel command line: ro root=/dev/hdc1 console=ttyS0,57600n8
console=tty0 panic=3 apic=debug nmi_watchdog=2
---
> Kernel command line: ro root=/dev/hdc1 console=ttyS0,57600n8
console=tty0 panic=3 apic=debug nmi_watchdog=1
69c69
< Calibrating delay using timer specific routine.. 4802.79 BogoMIPS
(lpj=24013960)
---
> Calibrating delay using timer specific routine.. 4802.80 BogoMIPS
(lpj=24014009)
88a89
> activating NMI Watchdog ... done.
97c98
< ..... CPU clock speed is 2400.1215 MHz.
---
> ..... CPU clock speed is 2400.1221 MHz.
98a100
> APIC timer registered as dummy, due to nmi_watchdog=1!
213a216,217
> Clockevents: could not switch to one-shot mode: lapic is not functional.
> Could not switch to high resolution mode on CPU 0
Do you know why nmi_watchdog=1 disables high-resolution timers?
And why nmi_watchdog=1 implies APIC timer registered as dummy?
# cat /sys/devices/system/clocksource/clocksource0/available_clocksource
tsc acpi_pm pit jiffies
# cat /sys/devices/system/clocksource/clocksource0/current_clocksource
tsc
# cat /proc/timer_list
Timer List Version: v0.3
HRTIMER_MAX_CLOCK_BASES: 2
now at 4613373211613 nsecs
cpu: 0
clock 0:
.index: 0
.resolution: 10000000 nsecs
.get_time: ktime_get_real
.offset: 0 nsecs
active timers:
clock 1:
.index: 1
.resolution: 10000000 nsecs
.get_time: ktime_get
.offset: 0 nsecs
active timers:
#0: <cf2c1ec0>, it_real_fn, S:01
# expires at 4630663830511 nsecs [in 17290618898 nsecs]
.expires_next : 9223372036854775807 nsecs
.hres_active : 0
.nr_events : 0
.nohz_mode : 0
.idle_tick : 0 nsecs
.tick_stopped : 0
.idle_jiffies : 0
.idle_calls : 0
.idle_sleeps : 0
.idle_entrytime : 0 nsecs
.idle_sleeptime : 0 nsecs
.last_jiffies : 0
.next_jiffies : 0
.idle_expires : 0 nsecs
jiffies: 431306
Tick Device: mode: 0
Clock Event Device: pit
max_delta_ns: 27461866
min_delta_ns: 12571
mult: 5124677
shift: 32
mode: 2
next_event: 9223372036854775807 nsecs
set_next_event: pit_next_event
set_mode: init_pit_timer
event_handler: tick_handle_periodic_broadcast
tick_broadcast_mask: 00000001
tick_broadcast_oneshot_mask: 00000000
Tick Device: mode: 0
Clock Event Device: lapic
max_delta_ns: 1006581321
min_delta_ns: 1799
mult: 35793226
shift: 32
mode: 1
next_event: 0 nsecs
set_next_event: lapic_next_event
set_mode: lapic_timer_setup
event_handler: tick_handle_periodic
# cat /proc/interrupts
CPU0
0: 468721 IO-APIC-edge timer
4: 326 IO-APIC-edge serial
8: 1 IO-APIC-edge rtc
9: 0 IO-APIC-fasteoi acpi
15: 15964 IO-APIC-edge ide1
16: 4217 IO-APIC-fasteoi eth0
17: 2340 IO-APIC-fasteoi eth1
18: 2340 IO-APIC-fasteoi eth2
19: 2340 IO-APIC-fasteoi eth3
NMI: 468690
LOC: 0
ERR: 0
MIS: 0
Regards.
On Fri, 12 Oct 2007 11:18:24 +0200
John Sigler <[email protected]> wrote:
> Hello,
>
> I'm experiencing a full system lockup. I'm using an out-of-tree
> driver which I suspect is responsible. I'm trying to enable the NMI
> watchdog.
one thing worth a shot is enabling lockdep.. that often finds deadlocks
for you ;)
--
On Fri, 12 Oct 2007, John Sigler wrote:
> Steven Rostedt wrote:
>
> > John Sigler wrote:
> > APIC timer registered as dummy, due to nmi_watchdog=1!
> 213a216,217
> > Clockevents: could not switch to one-shot mode: lapic is not functional.
> > Could not switch to high resolution mode on CPU 0
>
> Do you know why nmi_watchdog=1 disables high-resolution timers?
>
> And why nmi_watchdog=1 implies APIC timer registered as dummy?
Crap, I forgot about that. Thomas explained why to me once, and I forgot.
Does it still crash? If not, does it crash if you turn off highres?
Or better yet, try turning off dynamic-ticks. We had a bug once before
that had a problem with the new RCU code and dynamic ticks.
-- Steve
Arjan van de Ven wrote:
> John Sigler wrote:
>
>> I'm experiencing a full system lockup. I'm using an out-of-tree
>> driver which I suspect is responsible. I'm trying to enable the NMI
>> watchdog.
>
> one thing worth a shot is enabling lockdep.. that often finds deadlocks
> for you ;)
I enabled every option I thought might be useful.
I booted the system, fired a serial console, bumped the priority of the
serial port IRQ handler to 80 and the priority of the shell in the
serial console to 70, set the console log level to 9 using SysRq.
I then connected via ssh, loaded the driver module (the output showed up
in the serial console), started 4 processes, and had a complete system
lock-up within 10 seconds.
Nothing on the serial console :-(
The system didn't even respond to SysRq...
How do kernel hackers debug these problems?
#
# Kernel hacking
#
CONFIG_TRACE_IRQFLAGS_SUPPORT=y
# CONFIG_PRINTK_TIME is not set
# CONFIG_ENABLE_MUST_CHECK is not set
CONFIG_MAGIC_SYSRQ=y
# CONFIG_UNUSED_SYMBOLS is not set
# CONFIG_DEBUG_FS is not set
# CONFIG_HEADERS_CHECK is not set
CONFIG_DEBUG_KERNEL=y
CONFIG_DEBUG_SHIRQ=y
CONFIG_DETECT_SOFTLOCKUP=y
CONFIG_SCHED_DEBUG=y
# CONFIG_SCHEDSTATS is not set
CONFIG_TIMER_STATS=y
CONFIG_DEBUG_SLAB=y
CONFIG_DEBUG_SLAB_LEAK=y
CONFIG_DEBUG_PREEMPT=y
CONFIG_DEBUG_RT_MUTEXES=y
CONFIG_DEBUG_PI_LIST=y
# CONFIG_RT_MUTEX_TESTER is not set
CONFIG_DEBUG_SPINLOCK=y
CONFIG_DEBUG_MUTEXES=y
CONFIG_DEBUG_LOCK_ALLOC=y
CONFIG_PROVE_LOCKING=y
CONFIG_LOCKDEP=y
# CONFIG_LOCK_STAT is not set
# CONFIG_DEBUG_LOCKDEP is not set
CONFIG_TRACE_IRQFLAGS=y
CONFIG_DEBUG_SPINLOCK_SLEEP=y
CONFIG_DEBUG_LOCKING_API_SELFTESTS=y
CONFIG_STACKTRACE=y
CONFIG_PREEMPT_TRACE=y
# CONFIG_EVENT_TRACE is not set
# CONFIG_FUNCTION_TRACE is not set
# CONFIG_WAKEUP_TIMING is not set
# CONFIG_CRITICAL_PREEMPT_TIMING is not set
# CONFIG_CRITICAL_IRQSOFF_TIMING is not set
# CONFIG_DEBUG_KOBJECT is not set
CONFIG_DEBUG_BUGVERBOSE=y
# CONFIG_DEBUG_INFO is not set
# CONFIG_DEBUG_VM is not set
# CONFIG_DEBUG_LIST is not set
# CONFIG_FRAME_POINTER is not set
CONFIG_FORCED_INLINING=y
# CONFIG_RCU_TORTURE_TEST is not set
# CONFIG_FAULT_INJECTION is not set
CONFIG_EARLY_PRINTK=y
CONFIG_DEBUG_STACKOVERFLOW=y
# CONFIG_DEBUG_STACK_USAGE is not set
# CONFIG_DEBUG_PAGEALLOC is not set
CONFIG_DEBUG_RODATA=y
CONFIG_4KSTACKS=y
CONFIG_X86_FIND_SMP_CONFIG=y
CONFIG_X86_MPPARSE=y
CONFIG_DOUBLEFAULT=y
Steven Rostedt wrote:
> --
(Strange characters.)
> John Sigler wrote:
>
>> APIC timer registered as dummy, due to nmi_watchdog=1!
>> Clockevents: could not switch to one-shot mode: lapic is not functional.
>> Could not switch to high resolution mode on CPU 0
>>
>> Do you know why nmi_watchdog=1 disables high-resolution timers?
>>
>> And why nmi_watchdog=1 implies APIC timer registered as dummy?
>
> Crap, I forgot about that. Thomas explained why to me once, and I forgot.
Thomas,
Could you explain again why using the IO-APIC watchdog disables hrt?
> Does it still crash? If not, does it crash if you turn off highres?
It's not that simple. My app depends on hrt. I'd have to tweak it to
make it work when hrt are not available.
BTW, it's not a crash, it's a complete system lock-up. Nothing works,
and I really do mean nothing: ping is ignored, I can't open an ssh
connection, the serial console won't budge, even if I send SysRq combos...
> Or better yet, try turning off dynamic-ticks. We had a bug once before
> that had a problem with the new RCU code and dynamic ticks.
I didn't enable dynamic-ticks kernel support.
CONFIG_TICK_ONESHOT=y
# CONFIG_NO_HZ is not set
CONFIG_HIGH_RES_TIMERS=y
CONFIG_GENERIC_CLOCKEVENTS_BUILD=y
# CONFIG_SMP is not set
CONFIG_X86_PC=y
...
# CONFIG_HPET_TIMER is not set
# CONFIG_PREEMPT_NONE is not set
# CONFIG_PREEMPT_VOLUNTARY is not set
# CONFIG_PREEMPT_DESKTOP is not set
CONFIG_PREEMPT_RT=y
CONFIG_PREEMPT=y
CONFIG_PREEMPT_SOFTIRQS=y
CONFIG_PREEMPT_HARDIRQS=y
CONFIG_PREEMPT_BKL=y
# CONFIG_CLASSIC_RCU is not set
CONFIG_PREEMPT_RCU=y
# CONFIG_RCU_TRACE is not set
CONFIG_X86_UP_APIC=y
CONFIG_X86_UP_IOAPIC=y
CONFIG_X86_LOCAL_APIC=y
CONFIG_X86_IO_APIC=y
# CONFIG_X86_MCE is not set
# CONFIG_VM86 is not set
# CONFIG_TOSHIBA is not set
# CONFIG_I8K is not set
# CONFIG_X86_REBOOTFIXUPS is not set
# CONFIG_MICROCODE is not set
# CONFIG_X86_MSR is not set
Regards.