kern/40945: system process locked at 100% CPU

To: kern-bug-people%netbsd.org@localhost,gnats-admin%netbsd.org@localhost,netbsd-bugs%netbsd.org@localhost
Subject: kern/40945: system process locked at 100% CPU
From: okayawright%gmail.com@localhost
Date: Mon, 2 Mar 2009 21:00:12 +0000 (UTC)
>Number:         40945
>Category:       kern
>Synopsis:       system process locked at 100% CPU
>Confidential:   no
>Severity:       serious
>Priority:       high
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Mar 02 21:00:12 +0000 2009
>Originator:     okay_awright
>Release:        NetBSD 5.0RC2 (releng binaries)
>Organization:
>Environment:
NetBSD XXX.XXX.XXX 5.0_RC2 NetBSD 5.0_RC2 (GENERIC) #0: Mon Feb  9 03:56:31 UTC 
2009  
builds%b6.netbsd.org@localhost:/home/builds/ab/netbsd-5-0-RC2/amd64/200902090142Z-obj/home/builds/ab/netbsd-5-0-RC2/src/sys/arch/amd64/compile/GENERIC
 amd64

>Description:
Note: this PR has already been sent out but to the wrong category (port-amd64), 
it would be better listed under the kernel part IMO. I couldn't find a way to 
remove the other report or move it in this section so I duplicated it.

Symptom:
On an almost "bare" system, freshly installed, the cpu usage reported by both 
TOP and PS comes near 100% for one processor on an SMP system, and never stops 
(even if completely idling).

The box runs a GENERIC kernel, unmodified.

TOP output:
[root@XXX dummy]# top
load averages:  0.00,  0.03,  0.00;               up 0+00:32:59                 
                                                                                
     20:48:21
29 processes: 1 runnable, 26 sleeping, 2 on CPU
CPU0 states:  0.0% user,  0.0% nice,  0.0% system,  0.6% interrupt, 99.4% idle
CPU1 states:  0.0% user,  0.0% nice,  0.4% system,  0.0% interrupt, 99.6% idle
CPU2 states:  0.0% user,  0.0% nice,  0.0% system,  0.4% interrupt, 99.6% idle
CPU3 states:  0.0% user,  0.0% nice,  100% system,  0.0% interrupt,  0.0% idle
Memory: 102M Act, 1232K Wired, 15M Exec, 27M File, 1829M Free
Swap: 3072M Total, 3072M Free


  PID USERNAME PRI NICE   SIZE   RES STATE      TIME   WCPU    CPU COMMAND
    0 root      96    0     0K   11M CPU/3     14:38 99.02% 99.02% [system]
  455 mysql     85    0  7644K   23M select/2   0:03  0.00%  0.00% mysqld
  311 root      85    0  9852K   12M RUN/2      0:01  0.00%  0.00% squid
  682 root      43    0    96K 1384K CPU/2      0:00  0.00%  0.00% top
  182 named     85    0  2444K   11M sigwai/2   0:00  0.00%  0.00% named
  562 root      85    0   344K 4344K netio/2    0:00  0.00%  0.00% sshd
  507 dummy     85    0   344K 3328K select/1   0:00  0.00%  0.00% sshd
  396 postfix   85    0   264K 2408K kqueue/3   0:00  0.00%  0.00% qmgr
  522 postfix   85    0   208K 2380K kqueue/0   0:00  0.00%  0.00% pickup
  433 root      85    0   152K 2328K kqueue/2   0:00  0.00%  0.00% master
  297 root      85    0   284K 2044K select/2   0:00  0.00%  0.00% sshd
  579 root      85    0   988K 1952K wait/2     0:00  0.00%  0.00% bash
  568 dummy     85    0   928K 1884K wait/2     0:00  0.00%  0.00% bash
  493 squid     85    0   176K 1864K select/1   0:00  0.00%  0.00% pinger
  302 root      85    0  3300K 1760K wait/1     0:00  0.00%  0.00% squid
  517 squid     85    0    68K 1600K msgwai/2   0:00  0.00%  0.00% diskd
  350 squid     85    0    56K 1596K piperd/1   0:00  0.00%  0.00% unlinkd
  436 root      85    0   160K 1216K wait/2     0:00  0.00%  0.00% sh
  143 root      85    0    76K 1144K kqueue/2   0:00  0.00%  0.00% syslogd
  477 root      85    0    52K 1124K ttyraw/0   0:00  0.00%  0.00% getty
  467 root      85    0    52K 1124K ttyraw/1   0:00  0.00%  0.00% getty
  441 root      85    0    52K 1124K ttyraw/2   0:00  0.00%  0.00% getty
  474 root      85    0    52K 1124K ttyraw/3   0:00  0.00%  0.00% getty
    1 root      85    0    44K 1076K wait/2     0:00  0.00%  0.00% init
   95 root      85    0   472K 1028K select/2   0:00  0.00%  0.00% dhclient
  444 root      85    0    56K 1020K kqueue/2   0:00  0.00%  0.00% inetd
  459 root      85    0    56K 1016K nanosl/3   0:00  0.00%  0.00% cron
  164 root      85    0   120K  840K nanosl/1   0:00  0.00%  0.00% ipmon
  198 root      85    0   208K  816K mfsidl/2   0:00  0.00%  0.00% mount_mfs




PS output:
[root@XXX dummy]# ps -aux
USER    PID %CPU %MEM  VSZ   RSS TTY    STAT STARTED     TIME COMMAND
root      0 99.2  0.5    0 11072 ?      OKl   8:15PM 24:27.67 [system]
root      1  0.0  0.1   44  1076 ?      Is    8:15PM  0:00.01 init 
root     95  0.0  0.0  472  1028 ?      Is    8:15PM  0:00.00 /sbin/dhclient 
re0 
root    143  0.0  0.1   76  1144 ?      Ss    8:15PM  0:00.01 /usr/sbin/syslogd 
-P /var/run/syslogd.sockets -ss 
root    164  0.0  0.0  120   840 ?      Ss    8:15PM  0:00.25 /usr/sbin/ipmon 
-Ds 
named   182  0.0  0.6 2444 11672 ?      Isl   8:16PM  0:00.05 /usr/sbin/named 
-u named -t /var/chroot/named -c /etc/namedb/named.conf 
root    198  0.0  0.0  208   816 ?      Is    8:16PM  0:00.00 mount_mfs -s 
1049328 /dev/wd0b /tmp 
root    297  0.0  0.1  284  2044 ?      Is    8:16PM  0:00.00 /usr/sbin/sshd 
root    302  0.0  0.1 3300  1760 ?      Is    8:16PM  0:00.00 
/usr/pkg/sbin/squid -Y -f /usr/pkg/etc/squid/squid.conf 
squid   311  0.0  0.6 9852 12356 ?      S     8:16PM  0:02.37 (squid) -Y -f 
/usr/pkg/etc/squid/squid.conf (squid)
squid   350  0.0  0.1   56  1596 ?      Is    8:16PM  0:00.01 (unlinkd) 
(unlinkd)
postfix 396  0.0  0.1  264  2408 ?      I     8:16PM  0:00.02 qmgr -l -t unix 
-u 
root    433  0.0  0.1  152  2328 ?      Ss    8:16PM  0:00.04 
/usr/libexec/postfix/master 
root    444  0.0  0.0   56  1020 ?      Is    8:16PM  0:00.00 /usr/sbin/inetd 
-l 
mysql   455  0.0  1.1 7644 23532 ?      Il    8:16PM  0:03.36 
/usr/pkglibexec/mysqld --basedir=/usr/pkg --datadir=/var/mysql --user=mysql 
--pid-file=/var/mysql/XXX
root    459  0.0  0.0   56  1016 ?      Ss    8:16PM  0:00.01 /usr/sbin/cron 
squid   493  0.0  0.1  176  1864 ?      Ss    8:16PM  0:00.03 (pinger) (pinger)
dummy   507  0.0  0.2  344  3328 ?      S     8:18PM  0:00.19 sshd: dummy@pts/0 
(sshd)
squid   517  0.0  0.1   68  1600 ?      Ss    8:16PM  0:00.07 diskd 318468 
318469 318470 
postfix 522  0.0  0.1  208  2380 ?      S     8:16PM  0:00.02 pickup -l -t fifo 
-u 
root    562  0.0  0.2  344  4344 ?      Is    8:18PM  0:00.04 sshd: dummy 
[priv] 
dummy   568  0.0  0.1  928  1884 ttyp0  Is    8:18PM  0:00.01 -bash 
root    579  0.0  0.1  988  1952 ttyp0  S     8:18PM  0:00.09 bash 
root    589  0.0  0.0   60   976 ttyp0  O+    8:58PM  0:00.00 ps -aux 
root    436  0.0  0.1  160  1216 ttyE0- I     8:16PM  0:00.01 /bin/sh 
/usr/pkg/bin/mysqld_safe --user=mysql --datadir=/var/mysql 
--pid-file=/var/mysql/XXX.XXX.XXX.
root    441  0.0  0.1   52  1124 ttyE0  Is+   8:16PM  0:00.01 
/usr/libexec/getty Pc console 
root    477  0.0  0.1   52  1124 ttyE1  Is+   8:16PM  0:00.01 
/usr/libexec/getty Pc ttyE1 
root    467  0.0  0.1   52  1124 ttyE2  Is+   8:16PM  0:00.01 
/usr/libexec/getty Pc ttyE2 
root    474  0.0  0.1   52  1124 ttyE3  Is+   8:16PM  0:00.01 
/usr/libexec/getty Pc ttyE3 


dmesg output:
[root@XXX dummy]# dmesg
Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007, 2008
    The NetBSD Foundation, Inc.  All rights reserved.
Copyright (c) 1982, 1986, 1989, 1991, 1993
    The Regents of the University of California.  All rights reserved.


NetBSD 5.0_RC2 (GENERIC) #0: Mon Feb  9 03:56:31 UTC 2009
        
builds%b6.netbsd.org@localhost:/home/builds/ab/netbsd-5-0-RC2/amd64/200902090142Z-obj/home/builds/ab/netbsd-5-0-RC2/src/sys/arch/amd64/compile/GENERIC
total memory = 2037 MB
avail memory = 1960 MB
timecounter: Timecounters tick every 10.000 msec
timecounter: Timecounter "i8254" frequency 1193182 Hz quality 100
SMBIOS rev. 2.4 @ 0xe3590 (23 entries)
                                                                  (             
           )
mainbus0 (root)
cpu0 at mainbus0 apid 0: Intel 686-class, 1596MHz, id 0x106c2
cpu1 at mainbus0 apid 2: Intel 686-class, 1596MHz, id 0x106c2
cpu2 at mainbus0 apid 1: Intel 686-class, 1596MHz, id 0x106c2
cpu3 at mainbus0 apid 3: Intel 686-class, 1596MHz, id 0x106c2
ioapic0 at mainbus0 apid 2: pa 0xfec00000, version 20, 24 pins
acpi0 at mainbus0: Intel ACPICA 20080321
acpi0: X/RSDT: OemId <INTEL ,D945GLF2,00000063>, AslId <    ,01000013>
acpi0: SCI interrupting at int 9
acpi0: fixed-feature power button present
timecounter: Timecounter "ACPI-Fast" frequency 3579545 Hz quality 1000
ACPI-Fast 24-bit timer
acpibut0 at acpi0 (SLPB, PNP0C0E): ACPI Sleep Button
attimer1 at acpi0 (TMR, PNP0100): AT Timer
attimer1: io 0x40-0x43,0x50-0x53 irq 0
pcppi1 at acpi0 (SPKR, PNP0800)
pcppi1: io 0x61
midi0 at pcppi1: PC speaker (CPU-intensive output)
sysbeep0 at pcppi1
pckbc1 at acpi0 (PS2K, PNP0303): kbd port
pckbc1: io 0x60,0x64 irq 1
UAR1 (PNP0501) at acpi0 not configured
APIC (PNP0003) at acpi0 not configured
hpet0 at acpi0 (HPET, PNP0103)
hpet0: mem 0xfed00000-0xfed003ff
timecounter: Timecounter "hpet0" frequency 14318179 Hz quality 2000
attimer1: attached to pcppi1
pckbd0 at pckbc1 (kbd slot)
pckbc1: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard
pci0 at mainbus0 bus 0: configuration mode 1
pci0: i/o space, memory space enabled, rd/line, rd/mult, wr/inv ok
pchb0 at pci0 dev 0 function 0
pchb0: vendor 0x8086 product 0x2770 (rev. 0x02)
pchb0: returns constant 0xff stream, RNG disabled.
agp0 at pchb0: detected 7932k stolen memory
agp0: aperture at 0x80000000, size 0x10000000
vga0 at pci0 dev 2 function 0: vendor 0x8086 product 0x2772 (rev. 0x02)
wsdisplay0 at vga0 kbdmux 1: console (80x25, vt100 emulation), using wskbd0
wsmux1: connecting to wsdisplay0
drm at vga0 not configured
ppb0 at pci0 dev 28 function 0: vendor 0x8086 product 0x27d0 (rev. 0x01)
pci1 at ppb0 bus 1
pci1: i/o space, memory space enabled, rd/line, wr/inv ok
re0 at pci1 dev 0 function 0: RealTek 8168B/8111B PCIe Gigabit Ethernet (rev. 
0x02)
re0: interrupting at ioapic0 pin 16
re0: Unknown revision (0x3c400000)
re0: Ethernet address 00:1c:c0:8d:03:b2
re0: using 256 tx descriptors
rgephy0 at re0 phy 7: RTL8169S/8110S/8211 1000BASE-T media interface, rev. 2
rgephy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 
1000baseT-FDX, auto
ppb1 at pci0 dev 28 function 2: vendor 0x8086 product 0x27d4 (rev. 0x01)
pci2 at ppb1 bus 2
pci2: i/o space, memory space enabled, rd/line, wr/inv ok
ppb2 at pci0 dev 28 function 3: vendor 0x8086 product 0x27d6 (rev. 0x01)
pci3 at ppb2 bus 3
pci3: i/o space, memory space enabled, rd/line, wr/inv ok
uhci0 at pci0 dev 29 function 0: vendor 0x8086 product 0x27c8 (rev. 0x01)
uhci0: interrupting at ioapic0 pin 23
usb0 at uhci0: USB revision 1.0
uhci1 at pci0 dev 29 function 1: vendor 0x8086 product 0x27c9 (rev. 0x01)
uhci1: interrupting at ioapic0 pin 19
usb1 at uhci1: USB revision 1.0
uhci2 at pci0 dev 29 function 2: vendor 0x8086 product 0x27ca (rev. 0x01)
uhci2: interrupting at ioapic0 pin 18
usb2 at uhci2: USB revision 1.0
uhci3 at pci0 dev 29 function 3: vendor 0x8086 product 0x27cb (rev. 0x01)
uhci3: interrupting at ioapic0 pin 16
usb3 at uhci3: USB revision 1.0
ehci0 at pci0 dev 29 function 7: vendor 0x8086 product 0x27cc (rev. 0x01)
ehci0: interrupting at ioapic0 pin 23
ehci0: EHCI version 1.0
ehci0: companion controllers, 2 ports each: uhci0 uhci1 uhci2 uhci3
usb4 at ehci0: USB revision 2.0
ppb3 at pci0 dev 30 function 0: vendor 0x8086 product 0x244e (rev. 0xe1)
pci4 at ppb3 bus 4
pci4: i/o space, memory space enabled
re1 at pci4 dev 0 function 0: D-Link DGE-528T Gigabit Ethernet (rev. 0x10)
re1: interrupting at ioapic0 pin 21
re1: Ethernet address 00:21:91:0b:e7:84
re1: using 256 tx descriptors
rgephy1 at re1 phy 7: RTL8169S/8110S/8211 1000BASE-T media interface, rev. 3
rgephy1: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 
1000baseT-FDX, auto
ichlpcib0 at pci0 dev 31 function 0
ichlpcib0: vendor 0x8086 product 0x27b8 (rev. 0x01)
timecounter: Timecounter "ichlpcib0" frequency 3579545 Hz quality 1000
ichlpcib0: 24-bit timer
ichlpcib0: TCO (watchdog) timer configured.
piixide0 at pci0 dev 31 function 1
piixide0: Intel 82801GB/GR IDE Controller (ICH7) (rev. 0x01)
piixide0: bus-master DMA support present
piixide0: primary channel configured to compatibility mode
piixide0: primary channel interrupting at ioapic0 pin 14
atabus0 at piixide0 channel 0
piixide0: secondary channel configured to compatibility mode
piixide0: secondary channel ignored (disabled)
piixide1 at pci0 dev 31 function 2
piixide1: Intel 82801GB/GR Serial ATA/Raid Controller (ICH7) (rev. 0x01)
piixide1: bus-master DMA support present
piixide1: primary channel configured to native-PCI mode
piixide1: using ioapic0 pin 19 for native-PCI interrupt
atabus1 at piixide1 channel 0
piixide1: secondary channel configured to native-PCI mode
atabus2 at piixide1 channel 1
ichsmb0 at pci0 dev 31 function 3: vendor 0x8086 product 0x27da (rev. 0x01)
ichsmb0: interrupting at ioapic0 pin 19
iic0 at ichsmb0: I2C bus
isa0 at ichlpcib0
com0 at isa0 port 0x3f8-0x3ff irq 4: ns16550a, working fifo
timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
uhub0 at usb0: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhub1 at usb1: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhub2 at usb2: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhub3 at usb3: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub3: 2 ports with 2 removable, self powered
uhub4 at usb4: vendor 0x8086 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub4: 8 ports with 8 removable, self powered
wd0 at atabus1 drive 0: <OCZ SOLID_SSD>
wd0: drive supports 1-sector PIO transfers, LBA addressing
wd0: 30560 MB, 62090 cyl, 16 head, 63 sec, 512 bytes/sect x 62586880 sectors
wd0: 32-bit data port
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
wd0(piixide1:0:0): using PIO mode 4, Ultra-DMA mode 5 (Ultra/100) (using DMA)
wd1 at atabus2 drive 0: <SAMSUNG HM160HI>
wd1: drive supports 16-sector PIO transfers, LBA48 addressing
wd1: 149 GB, 310101 cyl, 16 head, 63 sec, 512 bytes/sect x 312581808 sectors
wd1: 32-bit data port
wd1: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 7
wd1(piixide1:1:0): using PIO mode 4, Ultra-DMA mode 6 (Ultra/133) (using DMA)
Kernelized RAIDframe activated
pad0: outputs: 44100Hz, 16-bit, stereo
audio0 at pad0: half duplex
boot device: wd0
root on wd0a dumps on wd0b
root file system type: ffs
wsdisplay0: screen 1 added (80x25, vt100 emulation)
wsdisplay0: screen 2 added (80x25, vt100 emulation)
wsdisplay0: screen 3 added (80x25, vt100 emulation)
wsdisplay0: screen 4 added (80x25, vt100 emulation)

NetBSD currently runs on this hardware:
-OCZ Solid Series 30 Go S-ATA II
-Intel® D945GCLF2
-D-Link DGE-528T
-G.Skill Extreme2 2 Go PC5300 PQ
-Samsung SpinPoint M5S - 160 Go S-ATA

>How-To-Repeat:
Install NetBSD 5.0RC2 on this hardware
>Fix:
no workaround found on my end, yet
Follow-Ups:
- Re: kern/40945: system process locked at 100% CPU
  - From: Christos Zoulas
Prev by Date: PR/39993 CVS commit: [netbsd-5] src/sys/dev/raidframe
Next by Date: Re: kern/40945: system process locked at 100% CPU
Previous by Thread: PR/39993 CVS commit: [netbsd-5] src/sys/dev/raidframe
Next by Thread: Re: kern/40945: system process locked at 100% CPU
Indexes:
Home | Main Index | Thread Index | Old Index