NMI watchdog

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.

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

--

I've noticed on some boxes that nmi_watchdog=2 does what you state. Try out nmi_watchdog=1.

-- Steve

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.

# 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
---

69c69
< Calibrating delay using timer specific routine.. 4802.79 BogoMIPS (lpj=24013960)
---

88a89

97c98
< ..... CPU clock speed is 2400.1215 MHz.
---

98a100

213a216,217

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.

one thing worth a shot is enabling lockdep.. that often finds deadlocks for you ;)

--

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

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

(Strange characters.)

Thomas,

Could you explain again why using the IO-APIC watchdog disables hrt?

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...

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.