kern/104406: [ufs] Processes get stuck in "ufs" state under persistent CPU load

[Oleg Derevenetz]

The following reply was made to PR kern/104406; it has been noted by GNATS.

From: "Oleg Derevenetz" <oleg at vsi.ru>
To: <bug-followup at FreeBSD.org>, <doublef-ctm at yandex.ru>
Cc:  
Subject: Re: kern/104406: [ufs] Processes get stuck in "ufs" state under persistent CPU load
Date: Fri, 19 Oct 2007 17:36:27 +0400

 This problem experiences on our another AMD64 machine (also with 6-STABLE). When we copy large amount of small files using mc from 
 FTP to local filesystem, after some time mc hangs in "wdrain" state, and all other processes that need to access filesystem are 
 hangs in "ufs" state. There are some debug stuff:
 
 uname -a:
 
 FreeBSD serv13.vsi.ru 6.2-STABLE FreeBSD 6.2-STABLE #1: Fri Oct 19 16:28:07 MSD 2007 
 oleg at serv13.vsi.ru:/usr/obj/usr/src/sys/serv13  i386
 
 dmesg:
 
 Copyright (c) 1992-2007 The FreeBSD Project.
 Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
         The Regents of the University of California. All rights reserved.
 FreeBSD is a registered trademark of The FreeBSD Foundation.
 FreeBSD 6.2-STABLE #1: Fri Oct 19 16:28:07 MSD 2007
     oleg at serv13.vsi.ru:/usr/obj/usr/src/sys/serv13
 WARNING: WITNESS option enabled, expect reduced performance.
 WARNING: DIAGNOSTIC option enabled, expect reduced performance.
 Timecounter "i8254" frequency 1193182 Hz quality 0
 CPU: Dual-Core AMD Opteron(tm) Processor 2212 (2010.31-MHz 686-class CPU)
   Origin = "AuthenticAMD"  Id = 0x40f12  Stepping = 2
   Features=0x178bfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,MMX,FXSR,SSE,SSE2,HTT>
   Features2=0x2001<SSE3,CX16>
   AMD Features=0xea500800<SYSCALL,NX,MMX+,FFXSR,RDTSCP,LM,3DNow!+,3DNow!>
   AMD Features2=0x1f<LAHF,CMP,SVM,ExtAPIC,CR8>
   Cores per package: 2
 real memory  = 3220176896 (3071 MB)
 avail memory = 3149598720 (3003 MB)
 ACPI APIC Table: <PTLTD          APIC  >
 FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
  cpu0 (BSP): APIC ID:  0
  cpu1 (AP): APIC ID:  1
  cpu2 (AP): APIC ID:  2
  cpu3 (AP): APIC ID:  3
 ioapic0 <Version 1.1> irqs 0-23 on motherboard
 ioapic1 <Version 1.1> irqs 24-47 on motherboard
 kbd1 at kbdmux0
 acpi0: <PTLTD   RSDT> on motherboard
 acpi0: Power Button (fixed)
 Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000
 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0
 cpu0: <ACPI CPU> on acpi0
 cpu1: <ACPI CPU> on acpi0
 cpu2: <ACPI CPU> on acpi0
 cpu3: <ACPI CPU> on acpi0
 acpi_button0: <Power Button> on acpi0
 pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
 pci0: <ACPI PCI bus> on pcib0
 pci0: <memory, RAM> at device 0.0 (no driver attached)
 isab0: <PCI-ISA bridge> port 0x1c00-0x1c7f at device 1.0 on pci0
 isa0: <ISA bus> on isab0
 pci0: <serial bus, SMBus> at device 1.1 (no driver attached)
 ohci0: <OHCI (generic) USB controller> mem 0xc0040000-0xc0040fff irq 16 at device 2.0 on pci0
 ohci0: [GIANT-LOCKED]
 usb0: OHCI version 1.0, legacy support
 usb0: SMM does not respond, resetting
 usb0: <OHCI (generic) USB controller> on ohci0
 usb0: USB revision 1.0
 uhub0: nVidia OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
 uhub0: 10 ports with 10 removable, self powered
 ehci0: <EHCI (generic) USB 2.0 controller> mem 0xc0041000-0xc00410ff irq 17 at device 2.1 on pci0
 ehci0: [GIANT-LOCKED]
 usb1: EHCI version 1.0
 usb1: companion controller, 10 ports each: usb0
 usb1: <EHCI (generic) USB 2.0 controller> on ehci0
 usb1: USB revision 2.0
 uhub1: nVidia EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
 uhub1: 10 ports with 10 removable, self powered
 atapci0: <nVidia nForce MCP55 UDMA133 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x3480-0x348f at device 4.0 on pci0
 ata0: <ATA channel 0> on atapci0
 ata1: <ATA channel 1> on atapci0
 pcib1: <ACPI PCI-PCI bridge> at device 6.0 on pci0
 pci1: <ACPI PCI bus> on pcib1
 pcib2: <PCI-PCI bridge> at device 4.0 on pci1
 pci2: <PCI bus> on pcib2
 mly0: <Mylex AcceleRAID 170> mem 0xc0600000-0xc0601fff irq 20 at device 4.1 on pci1
 mly0: [GIANT-LOCKED]
 mly0: AcceleRAID 170  , 1 channel, firmware 6.00-7-00 (20001214), 32MB RAM
 pci0: <bridge> at device 8.0 (no driver attached)
 pci0: <bridge> at device 9.0 (no driver attached)
 pcib3: <ACPI PCI-PCI bridge> at device 13.0 on pci0
 pci3: <ACPI PCI bus> on pcib3
 pcib4: <ACPI PCI-PCI bridge> at device 0.0 on pci3
 pci4: <ACPI PCI bus> on pcib4
 fxp0: <Intel 82559 Pro/100 Ethernet> port 0x4000-0x403f mem 0xc0300000-0xc0300fff,0xc0200000-0xc02fffff irq 22 at device 9.0 on pci4
 miibus0: <MII bus> on fxp0
 inphy0: <i82555 10/100 media interface> on miibus0
 inphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
 fxp0: Ethernet address: 00:d0:b7:1c:80:7e
 pcib5: <ACPI PCI-PCI bridge> mem 0xc0100000-0xc010007f irq 21 at device 0.1 on pci3
 pci5: <ACPI PCI bus> on pcib5
 pcib6: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
 pci128: <ACPI PCI bus> on pcib6
 pci128: <memory, RAM> at device 0.0 (no driver attached)
 pci128: <memory, RAM> at device 1.0 (no driver attached)
 pci128: <serial bus, SMBus> at device 1.1 (no driver attached)
 pcib7: <ACPI PCI-PCI bridge> at device 13.0 on pci128
 pci129: <ACPI PCI bus> on pcib7
 pcib8: <ACPI PCI-PCI bridge> at device 15.0 on pci128
 pci130: <ACPI PCI bus> on pcib8
 pci130: <display, VGA> at device 0.0 (no driver attached)
 atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
 atkbd0: <AT Keyboard> irq 1 on atkbdc0
 kbd0 at atkbd0
 atkbd0: [GIANT-LOCKED]
 sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
 sio0: type 16550A
 fdc0: <floppy drive controller> port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
 fdc0: [FAST]
 pmtimer0 on isa0
 orm0: <ISA Option ROMs> at iomem 0xc0000-0xcefff,0xcf000-0xd07ff on isa0
 ppc0: <Parallel port> at port 0x278-0x27f irq 7 on isa0
 ppc0: Generic chipset (EPP/NIBBLE) in COMPATIBLE mode
 ppbus0: <Parallel port bus> on ppc0
 plip0: <PLIP network interface> on ppbus0
 lpt0: <Printer> on ppbus0
 lpt0: Interrupt-driven port
 ppi0: <Parallel I/O> on ppbus0
 sc0: <System console> at flags 0x100 on isa0
 sc0: VGA <16 virtual consoles, flags=0x300>
 sio1: configured irq 3 not in bitmap of probed irqs 0
 sio1: port may not be enabled
 vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
 Timecounters tick every 1.000 msec
 IP Filter: v4.1.13 initialized.  Default = block all, Logging = enabled
 ipfw2 (+ipv6) initialized, divert loadable, rule-based forwarding disabled, default to accept, logging disabled
 acd0: CDROM <NEC CD-ROM CD-3002A/C000> at ata0-master UDMA33
 da0 at mly0 bus 1 target 0 lun 0
 da0: <RAID 7 online > Fixed Direct Access SCSI-3 device
 da0: 135.168MB/s transfers
 da0: 34712MB (71090176 512 byte sectors: 255H 63S/T 4425C)
 da1 at mly0 bus 1 target 1 lun 0
 da1: <RAID 7 online > Fixed Direct Access SCSI-3 device
 da1: 135.168MB/s transfers
 da1: 34712MB (71090176 512 byte sectors: 255H 63S/T 4425C)
 SMP: AP CPU #3 Launched!
 SMP: AP CPU #2 Launched!
 SMP: AP CPU #1 Launched!
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da1:mly0:1:1:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da1:mly0:1:1:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 (da0:mly0:1:0:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da0:mly0:1:0:0): Sense Error Code 0x0
 Trying to mount root from ufs:/dev/da0s1a
 WARNING: / was not properly dismounted
 (da1:mly0:1:1:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da1:mly0:1:1:0): Sense Error Code 0x0
 (da1:mly0:1:1:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da1:mly0:1:1:0): Sense Error Code 0x0
 (da1:mly0:1:1:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da1:mly0:1:1:0): Sense Error Code 0x0
 (da1:mly0:1:1:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da1:mly0:1:1:0): Sense Error Code 0x0
 (da1:mly0:1:1:0): SYNCHRONIZE CACHE. CDB: 35 0 0 0 0 0 0 0 0 0
 (da1:mly0:1:1:0): Sense Error Code 0x0
 acquiring duplicate lock of same type: "vnode interlock"
  1st vnode interlock @ /usr/src/sys/kern/vfs_vnops.c:806
  2nd vnode interlock @ /usr/src/sys/kern/vfs_subr.c:2039
 KDB: stack backtrace:
 kdb_backtrace(3,c80e6780,c07a89f0,c07a89f0,c07678a4,...) at kdb_backtrace+0x29
 witness_checkorder(c7eb0d04,9,c072db32,7f7) at witness_checkorder+0x578
 _mtx_lock_flags(c7eb0d04,0,c072db32,7f7,c8055980,...) at _mtx_lock_flags+0x78
 vrefcnt(c7eb0c3c) at vrefcnt+0x20
 null_checkvp(c81dac3c,c071c808,215) at null_checkvp+0x56
 null_lock(ea872a68) at null_lock+0x66
 VOP_LOCK_APV(c0760b20,ea872a68) at VOP_LOCK_APV+0x87
 vn_lock(c81dac3c,1002,c80e6780,c81dac3c,c81dae60,...) at vn_lock+0xac
 nullfs_root(c8209000,2,ea872ae0,c80e6780,0,8,0,c07e5fe0,0,c072d3b0,407) at nullfs_root+0x26
 vfs_domount(c80e6780,c8055100,c8055700,d,c8055030,c0797ae0,0,c072d3b0,2bf) at vfs_domount+0x975
 vfs_donmount(c80e6780,d,c80ede80,c80ede80,0,...) at vfs_donmount+0x3f9
 nmount(c80e6780,ea872d04) at nmount+0x8b
 syscall(3b,3b,3b,bfbfe5f5,bfbfeea0,...) at syscall+0x25b
 Xint0x80_syscall() at Xint0x80_syscall+0x1f
 --- syscall (378, FreeBSD ELF32, nmount), eip = 0x280bc11b, esp = 0xbfbfe5bc, ebp = 0xbfbfee38 ---
 Accounting enabled
 
 show pcpu:
 
 cpuid = 0
 curthread = 0xc7ce3300: pid 20 "swi6: Giant tasq"
 curpcb = 0xe68dbd90
 fpcurthread = none
 idlethread = 0xc7ce3a80: pid 13 "idle: cpu0"
 APIC ID = 0
 currentldt = 0x50
 spin locks held:
 
 show locks:
 
 exclusive sleep mutex Giant r = 0 (0xc0797ae0) locked @ /usr/src/sys/kern/kern_intr.c: 681
 
 show alllocks:
 
 Process 20 (swi6: Giant tasq) thread 0xc7ce3300 (100008)
 exclusive sleep mutex Giant r = 0 (0xc0797ae0) locked @ /usr/src/sys/kern/kern_intr.c: 681
 
 After getting a kernel dump I can obtain more information.
 
 --
 Oleg Derevenetz <oleg at vsi.ru> OOD3-RIPE
 Phone: +7 4732 539880
 Fax:   +7 4732 531415         http://www.vsi.ru
 CenterTelecom Voronezh ISP    http://isp.vsi.ru