Date: Sat, 19 Jul 2008 13:13:17 GMT From: David Adam <zanchey@ucc.gu.uwa.edu.au> To: freebsd-gnats-submit@FreeBSD.org Subject: misc/125769: getencstat(8) panics system with "Sleeping thread owns a non-sleepable lock" Message-ID: <200807191313.m6JDDHF8091770@www.freebsd.org> Resent-Message-ID: <200807191320.m6JDK1gf019386@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>Number: 125769 >Category: misc >Synopsis: getencstat(8) panics system with "Sleeping thread owns a non-sleepable lock" >Confidential: no >Severity: non-critical >Priority: low >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Sat Jul 19 13:20:01 UTC 2008 >Closed-Date: >Last-Modified: >Originator: David Adam >Release: 7.0-RELEASE-p3 >Organization: University Computer Club, UWA >Environment: FreeBSD blade.ucc.gu.uwa.edu.au 7.0-RELEASE-p3 FreeBSD 7.0-RELEASE-p3 #0: Fri Jul 18 22:50:06 WST 2008 root@:/usr/obj/usr/src/sys/GENERIC-DEBUG i386 SMP enabled Intel SR1200 Pentium 3-class system >Description: I have an ses(4) device which I was investigating using, so compiled /usr/share/examples/ses/getencstat and friends. ses0 at ahc1 bus 0 target 6 lun 0 ses0: <ESG-SHV SCA HSBP M18 0.06> Fixed Processor SCSI-2 device ses0: 3.300MB/s transfers ses0: SAF-TE Compliant Device Running getencstat(8) produces no output but repeatably panics the GENERIC kernel, complaining of "Sleeping thread (tid 100056, pid 57) owns a non-sleepable lock" in ahc_lock [irq26: ahc1]. Dumping core is not possible because the panic prevents any further SCSI traffic, but I have DDB available and can probably get remote GDB set up. I have attached a file containing a dmesg and my best guesses at useful DDB output - if I can provide anything more please let me know. >How-To-Repeat: 1. cd /usr/share/examples/ses/getencstat && make 2. cp /usr/share/examples/ses/getencstat/getencstat /tmp/getencstat 3. Reboot to single-user in order to prevent filesystem damage. 4. /tmp/getencstat /dev/ses0 This is repeatable both with the FreeBSD Update-provided kernel, and with a GENERIC-DEBUG kernel config containing include GENERIC options KDB options DDB options KDB_TRACE Kernel panics (or, in the file attached, enters DDB.) >Fix: Patch attached with submission follows: KDB: debugger backends: ddb KDB: current backend: ddb Copyright (c) 1992-2008 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 7.0-RELEASE-p3 #0: Fri Jul 18 22:50:06 WST 2008 root@:/usr/obj/usr/src/sys/GENERIC-DEBUG Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: Intel(R) Pentium(R) III CPU family 1133MHz (1130.46-MHz 686-class CPU) Origin = "GenuineIntel" Id = 0x6b1 Stepping = 1 Features=0x383fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE> real memory = 2147221504 (2047 MB) avail memory = 2091651072 (1994 MB) ACPI APIC Table: <INTEL SCB20 > FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs cpu0 (BSP): APIC ID: 3 cpu1 (AP): APIC ID: 0 MADT: Forcing active-low polarity and level trigger for SCI ioapic0 <Version 1.1> irqs 0-15 on motherboard ioapic1 <Version 1.1> irqs 16-31 on motherboard lapic3: Forcing LINT1 to edge trigger kbd1 at kbdmux0 ath_hal: 0.9.20.3 (AR5210, AR5211, AR5212, RF5111, RF5112, RF2413, RF5413) hptrr: HPT RocketRAID controller driver v1.1 (Jul 18 2008 22:49:23) acpi0: <INTEL SCB20> on motherboard ACPI Warning (dswload-0794): Type override - [DEB_] had invalid type (Integer) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [MLIB] had invalid type (Integer) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [DATA] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [SIO_] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [SB__] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [PM__] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [ICNT] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [ACPI] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [LEDP] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [WUES] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [WUSE] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [CSB5] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [PM__] had invalid type (String) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [BIOS] had invalid type (Integer) for Scope operator, changed to (Scope) [20070320] ACPI Warning (dswload-0794): Type override - [CMOS] had invalid type (Integer) for Scope operator, changed to (Scope) [20070320] acpi0: [ITHREAD] ACPI Error (evxfevnt-0288): Could not enable GlobalLock event [20070320] ACPI Warning (evxface-0235): Could not enable fixed event 1 [20070320] ACPI Error (evmisc-0487): No response from Global Lock hardware, disabling lock [20070320] acpi0: Power Button (fixed) Timecounter "ACPI-safe" frequency 3579545 Hz quality 850 acpi_timer0: <32-bit timer at 3.579545MHz> port 0x508-0x50b on acpi0 cpu0: <ACPI CPU> on acpi0 cpu1: <ACPI CPU> on acpi0 pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0 pci0: <ACPI PCI bus> on pcib0 fxp0: <Intel 82550 Pro/100 Ethernet> port 0x1400-0x143f mem 0xfe7e0000-0xfe7e0fff,0xfe7a0000-0xfe7bffff irq 21 at device 3.0 on pci0 miibus0: <MII bus> on fxp0 inphy0: <i82555 10/100 media interface> PHY 1 on miibus0 inphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto fxp0: Ethernet address: 00:03:47:a5:8e:84 fxp0: [ITHREAD] fxp1: <Intel 82550 Pro/100 Ethernet> port 0x1440-0x147f mem 0xfe780000-0xfe780fff,0xfe760000-0xfe77ffff irq 20 at device 4.0 on pci0 miibus1: <MII bus> on fxp1 inphy1: <i82555 10/100 media interface> PHY 1 on miibus1 inphy1: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto fxp1: Ethernet address: 00:03:47:a5:8e:86 fxp1: [ITHREAD] vgapci0: <VGA-compatible display> port 0x1000-0x10ff mem 0xfd000000-0xfdffffff,0xfe7f0000-0xfe7f0fff irq 18 at device 12.0 on pci0 isab0: <PCI-ISA bridge> at device 15.0 on pci0 isa0: <ISA bus> on isab0 atapci0: <ServerWorks CSB5 UDMA100 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x3a0-0x3af,0x410-0x413 at device 15.1 on pci0 ata0: <ATA channel 0> on atapci0 ata0: [ITHREAD] ata1: <ATA channel 1> on atapci0 ata1: [ITHREAD] ohci0: <OHCI (generic) USB controller> mem 0xfe740000-0xfe740fff irq 10 at device 15.2 on pci0 ohci0: [GIANT-LOCKED] ohci0: [ITHREAD] 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: <(0x1166) OHCI root hub, class 9/0, rev 1.00/1.00, addr 1> on usb0 uhub0: 4 ports with 4 removable, self powered pcib1: <ACPI Host-PCI bridge> on acpi0 pci1: <ACPI PCI bus> on pcib1 ahc0: <Adaptec aic7899 Ultra160 SCSI adapter> port 0x2400-0x24ff mem 0xfebe0000-0xfebe0fff irq 27 at device 7.0 on pci1 ahc0: [ITHREAD] aic7899: Ultra160 Wide Channel A, SCSI Id=7, 32/253 SCBs ahc1: <Adaptec aic7899 Ultra160 SCSI adapter> port 0x2000-0x20ff mem 0xfebf0000-0xfebf0fff irq 26 at device 7.1 on pci1 ahc1: [ITHREAD] aic7899: Ultra160 Wide Channel B, SCSI Id=7, 32/253 SCBs pcib2: <ACPI Host-PCI bridge> on acpi0 pci2: <ACPI PCI bus> on pcib2 atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0 atkbd0: <AT Keyboard> irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] atkbd0: [ITHREAD] fdc0: <floppy drive controller (FDE)> port 0x3f2-0x3f3,0x3f4-0x3f5,0x3f7 irq 6 drq 2 on acpi0 fdc0: [FILTER] fd0: <1440-KB 3.5" drive> on fdc0 drive 0 sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 on acpi0 sio0: type 16550A sio0: [FILTER] sio1: <16550A-compatible COM port> port 0x2f8-0x2ff irq 3 flags 0x10 on acpi0 sio1: type 16550A, console sio1: [FILTER] pmtimer0 on isa0 ipmi0: <IPMI System Interface> on isa0 ipmi0: KCS mode found at io 0xca2 alignment 0x1 on isa ipmi0: KCS Error Data ac orm0: <ISA Option ROMs> at iomem 0xc0000-0xc7fff,0xc8000-0xc97ff,0xc9800-0xcafff,0xcb000-0xd0fff pnpid ORM0000 on isa0 ppc0: parallel port not found. sc0: <System console> at flags 0x100 on isa0 sc0: VGA <16 virtual consoles, flags=0x300> vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 Timecounters tick every 1.000 msec hptrr: no controller detected. Waiting 5 seconds for SCSI devices to settle ipmi0: IPMI device rev. 1, firmware rev. 0.81, version 1.5 ipmi0: Number of channels 2 ipmi0: Attached watchdog ses0 at ahc1 bus 0 target 6 lun 0 ses0: <ESG-SHV SCA HSBP M18 0.06> Fixed Processor SCSI-2 device ses0: 3.300MB/s transfers ses0: SAF-TE Compliant Device da0 at ahc1 bus 0 target 0 lun 0 da0: <SEAGATE ST336704LSUN36G 032C> Fixed Direct Access SCSI-3 device da0: 160.000MB/s transfers (80.000MHz DT, offset 63, 16bit) da0: Command Queueing Enabled da0: 34732MB (71132959 512 byte sectors: 255H 63S/T 4427C) da1 at ahc1 bus 0 target 1 lun 0 da1: <FUJITSU MAP3367N SUN36G 0401> Fixed Direct Access SCSI-4 device da1: 160.000MB/s transfers (80.000MHz DT, offset 127, 16bit) da1: Command Queueing Enabled da1: 34732MB (71132959 512 byte sectors: 255H 63S/T 4427C) da2 at ahc1 bus 0 target 2 lun 0 da2: <COMPAQ BF0368A4CA HPB5> Fixed Direct Access SCSI-3 device da2: 160.000MB/s transfers (80.000MHz DT, offset 63, 16bit) da2: Command Queueing Enabled da2: 34732MB (71132000 512 byte sectors: 255H 63S/T 4427C) lapic0: Forcing LINT1 to edge trigger SMP: AP CPU #1 Launched! Trying to mount root from ufs:/dev/da0s1a <log in single user> # /tmp/getencstat /dev/ses0 Sleeping thread (tid 100056, pid 57) owns a non-sleepable lock sched_switch(c5545a50,0,1,1b85a24,7579d,...) at sched_switch+0x19d mi_switch(1,0,c5545a50,c5545a50,e7b85a60,...) at mi_switch+0x146 sleepq_switch(c5545a50,0,c0aebd49,230,0,...) at sleepq_switch+0xcb sleepq_wait(c54c8428,4c,c0ae9c4f,d8,0,...) at sleepq_wait+0x36 _sleep(c54c8428,c52b5d30,4c,c0aa4b6c,0) at _sleep+0x2d6 cam_periph_ccbwait(c54c8400,c5115380,1,201,1,...) at cam_periph_ccbwait+0x5c cam_periph_runccb(c54c8400,c04870c0,2,3,0,...) at cam_periph_runccb+0x50 ses_runcmd(c54da8e0,e7b85b80,1,c0a6e1a5,e7b85b68,...) at ses_runcmd+0xdd safte_rdstat(e7b85be4,c0489ea3,c54cc000,1,0,...) at safte_rdstat+0xa8 safte_get_encstat(c54cc000,1,0,0,0,...) at safte_get_encstat+0xe sesioctl(c533fc00,20005303,e7b85d04,1,c5545a50,...) at sesioctl+0x383 devfs_ioctl_f(c5527c18,20005303,e7b85d04,c50f3900,c5545a50,...) at devfs_ioctl_f+0xcb kern_ioctl(c5545a50,3,20005303,e7b85d04,7e3120,...) at kern_ioctl+0x355 ioctl(c5545a50,e7b85cfc,c,e7b85d38,e7b85d2c,...) at ioctl+0x134 syscall(e7b85d38) at syscall+0x335 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (54, FreeBSD ELF32, ioctl), eip = 0x28154373, esp = 0xbfbfeddc, ebp = 0xbfbfee38 --- panic: sleeping thread cpuid = 0 KDB: stack backtrace: db_trace_self_wrapper(c0aeb41d,e5948c20,c075ce8f,c0b0b8c4,0,...) at db_trace_self_wrapper+0x26 kdb_backtrace(c0b0b8c4,0,c0aec21c,e5948c2c,0,...) at kdb_backtrace+0x29 panic(c0aec21c,ffffffff,39,cb,c52b8420,...) at panic+0x10f propagate_priority(c52b8420,c50f1640,c0aec1bd,2d8,c0778988,...) at propagate_priority+0x11e turnstile_wait(c50f1640,c5545a50,0,c52b0800,c5156200,...) at turnstile_wait+0x2d8 _mtx_lock_sleep(c52b5d30,c52b8420,0,0,0,...) at _mtx_lock_sleep+0x10e ahc_platform_intr(c52b0800,0,c0ae7314,46b,0,...) at ahc_platform_intr+0x56 ithread_loop(c5302380,e5948d38,0,0,0,...) at ithread_loop+0x1ab fork_exit(c073f440,c5302380,e5948d38) at fork_exit+0x99 fork_trampoline() at fork_trampoline+0x8 --- trap 0, eip = 0, esp = 0xe5948d70, ebp = 0 --- KDB: enter: panic [thread pid 35 tid 100034 ] Stopped at kdb_enter+0x32: leave db> show reg cs 0x20 ds 0xc0780028 resource_list_alloc+0xd8 es 0xc0ae0028 fs 0xc0780008 resource_list_alloc+0xb8 ss 0x28 eax 0x12 ecx 0xc1435920 edx 0 ebx 0x100 esp 0xe5948bec ebp 0xe5948bf4 esi 0x1 edi 0xc52b8420 eip 0xc0783e82 kdb_enter+0x32 efl 0x86 kdb_enter+0x32: leave db> show all procs pid ppid pgrp uid state wmesg wchan cmd 57 55 57 0 S+ cbwait 0xc54c8428 getencstat 55 1 55 0 Ss+ wait 0xc550dab0 sh 54 0 0 0 SL - 0xc54f6300 [gv_v raid5] 53 0 0 0 SL - 0xc54f6200 [gv_p raid5.p0] 52 0 0 0 SL - 0xc54f2500 [gv_d rC] 51 0 0 0 SL - 0xc54f6800 [gv_d rB] 50 0 0 0 SL - 0xc54f2d00 [gv_d rA] 49 0 0 0 SL - 0xc0bf2d14 [schedcpu] 48 0 0 0 SL sdflush 0xc0c05064 [softdepflush] 47 0 0 0 SL syncer 0xc0bf2d0c [syncer] 46 0 0 0 SL vlruwt 0xc54d6000 [vnlru] 45 0 0 0 SL psleep 0xc0bf9824 [bufdaemon] 44 0 0 0 SL pgzero 0xc0c05c20 [pagezero] 43 0 0 0 SL psleep 0xc0c05838 [vmdaemon] 42 0 0 0 SL psleep 0xc0c05800 [pagedaemon] 41 0 0 0 SL ipmireq 0xc53290b4 [ipmi0: kcs] 40 0 0 0 SL waiting_ 0xc0bfb58c [sctp_iterator] 39 0 0 0 WL [swi0: sio] 38 0 0 0 SL - 0xc52b0e3c [fdc0] 37 0 0 0 WL [irq1: atkbd0] 36 0 0 0 SL idle 0xc52b0800 [aic_recovery1] 35 0 0 0 LL *ahc_lock 0xc50f1640 [irq26: ahc1] 34 0 0 0 SL idle 0xc52b0800 [aic_recovery1] 33 0 0 0 SL idle 0xc521e400 [aic_recovery0] 32 0 0 0 WL [irq27: ahc0] 31 0 0 0 SL idle 0xc521e400 [aic_recovery0] 30 0 0 0 SL usbtsk 0xc0bf09d4 [usbtask-dr] 29 0 0 0 SL usbtsk 0xc0bf09c0 [usbtask-hc] 28 0 0 0 SL usbevt 0xc52a8210 [usb0] 27 0 0 0 WL [irq10: ohci0] 26 0 0 0 WL [irq15: ata1] 25 0 0 0 WL [irq14: ata0] 24 0 0 0 WL [irq20: fxp1] 23 0 0 0 WL [irq21: fxp0] 22 0 0 0 WL [irq9: acpi0] 21 0 0 0 WL [swi5: +] 20 0 0 0 WL [swi2: cambio] 19 0 0 0 SL ccb_scan 0xc0bc1bd4 [xpt_thrd] 9 0 0 0 SL - 0xc5182280 [acpi_task_2] 8 0 0 0 SL - 0xc5182280 [acpi_task_1] 7 0 0 0 SL - 0xc5182280 [acpi_task_0] 6 0 0 0 SL - 0xc5182300 [kqueue taskq] 18 0 0 0 WL [swi6: task queue] 17 0 0 0 WL [swi6: Giant taskq] 5 0 0 0 SL - 0xc5182580 [thread taskq] 16 0 0 0 SL - 0xc0bf2d14 [yarrow] 4 0 0 0 SL - 0xc0bf0dac [g_down] 3 0 0 0 SL - 0xc0bf0da8 [g_up] 2 0 0 0 SL - 0xc0bf0da0 [g_event] 15 0 0 0 WL [swi1: net] 14 0 0 0 WL [swi3: vm] 13 0 0 0 WL [swi4: clock sio] 12 0 0 0 RL [idle: cpu0] 11 0 0 0 RL CPU 1 [idle: cpu1] 1 0 1 0 SLs wait 0xc5117ab0 [init] 10 0 0 0 SL audit_wo 0xc0c04ad4 [audit] 0 0 0 0 WLs [swapper] db> trace/u 57 Tracing pid 35 tid 100034 td 0xc52b8420 kdb_enter(c0ae9749,0,c0aec21c,e5948c2c,0,...) at kdb_enter+0x32 panic(c0aec21c,ffffffff,39,cb,c52b8420,...) at panic+0x124 propagate_priority(c52b8420,c50f1640,c0aec1bd,2d8,c0778988,...) at propagate_priority+0x11e turnstile_wait(c50f1640,c5545a50,0,c52b0800,c5156200,...) at turnstile_wait+0x2d8 _mtx_lock_sleep(c52b5d30,c52b8420,0,0,0,...) at _mtx_lock_sleep+0x10e ahc_platform_intr(c52b0800,0,c0ae7314,46b,0,...) at ahc_platform_intr+0x56 ithread_loop(c5302380,e5948d38,0,0,0,...) at ithread_loop+0x1ab fork_exit(c073f440,c5302380,e5948d38) at fork_exit+0x99 fork_trampoline() at fork_trampoline+0x8 --- trap 0, eip = 0, esp = 0xe5948d70, ebp = 0 --- db> trace 57 Tracing pid 57 tid 100056 td 0xc5545a50 sched_switch(c5545a50,0,1,1b85a24,7579d,...) at sched_switch+0x19d mi_switch(1,0,c5545a50,c5545a50,e7b85a60,...) at mi_switch+0x146 sleepq_switch(c5545a50,0,c0aebd49,230,0,...) at sleepq_switch+0xcb sleepq_wait(c54c8428,4c,c0ae9c4f,d8,0,...) at sleepq_wait+0x36 _sleep(c54c8428,c52b5d30,4c,c0aa4b6c,0) at _sleep+0x2d6 cam_periph_ccbwait(c54c8400,c5115380,1,201,1,...) at cam_periph_ccbwait+0x5c cam_periph_runccb(c54c8400,c04870c0,2,3,0,...) at cam_periph_runccb+0x50 ses_runcmd(c54da8e0,e7b85b80,1,c0a6e1a5,e7b85b68,...) at ses_runcmd+0xdd safte_rdstat(e7b85be4,c0489ea3,c54cc000,1,0,...) at safte_rdstat+0xa8 safte_get_encstat(c54cc000,1,0,0,0,...) at safte_get_encstat+0xe sesioctl(c533fc00,20005303,e7b85d04,1,c5545a50,...) at sesioctl+0x383 devfs_ioctl_f(c5527c18,20005303,e7b85d04,c50f3900,c5545a50,...) at devfs_ioctl_f+0xcb kern_ioctl(c5545a50,3,20005303,e7b85d04,7e3120,...) at kern_ioctl+0x355 ioctl(c5545a50,e7b85cfc,c,e7b85d38,e7b85d2c,...) at ioctl+0x134 syscall(e7b85d38) at syscall+0x335 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (54, FreeBSD ELF32, ioctl), eip = 0x28154373, esp = 0xbfbfeddc, ebp = 0xbfbfee38 --- db> show sysregs idtr 0xc0c18100/07ff gdtr 0xc0c16460/0097 ldtr 0x0050 tr 0x0048 cr0 0x8005003b cr2 0xe2459000 cr3 0x01a13000 cr4 0x00000691 db> x/wx $esp,10 0xe5948bec: c0aeb3f6 c0ae9749 e5948c20 c075cea4 0xe5948bfc: c0ae9749 0 c0aec21c e5948c2c 0xe5948c0c: 0 e5948c2c c50f1640 c5545a50 0xe5948c1c: 14 e5948c48 c078e65e c0aec21c db> reboot >Release-Note: >Audit-Trail: >Unformatted:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200807191313.m6JDDHF8091770>