Date: Sun, 18 Jan 2009 10:49:16 +0100 (CET) From: Martin Birgmeier <martin@email.aon.at> To: FreeBSD-gnats-submit@FreeBSD.org Subject: kern/130683: shutdown hangs after syncing disks - ACPI race? Message-ID: <200901180949.n0I9nGuu007252@gandalf.xyzzy> Resent-Message-ID: <200901181020.n0IAK0dE052026@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>Number: 130683 >Category: kern >Synopsis: shutdown hangs after syncing disks - ACPI race? >Confidential: no >Severity: serious >Priority: medium >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Sun Jan 18 10:20:00 UTC 2009 >Closed-Date: >Last-Modified: >Originator: Martin Birgmeier >Release: FreeBSD 7.1-RELEASE i386 >Organization: MBi at home >Environment: System: FreeBSD gandalf.xyzzy 7.1-RELEASE FreeBSD 7.1-RELEASE #0: Sun Jan 4 10:53:24 CET 2009 root@atpcdvvc.xyzzy:/usr/VOL/OBJ/FreeBSD/RELENG_7_1_0_RELEASE/src/sys/XYZZY i386 >Description: When trying to shutdown -p, the system hangs after syncing disks. I have a hunch that this is caused by a race in ACPI, and have therefore compiled a kernel with ACPI_DBUG. Now, when I use the following settings in /boot/loader.conf, debug.acpi.layer="ACPI_HARDWARE ACPI_EVENTS ACPI_POWER" debug.acpi.level="ACPI_LV_FUNCTIONS" the interesting thing is that I cannot even boot any more, but rather get a continuous stream of the following (copied manually from a screenshot taken using a digicam after pressing CTRL-ALT-ESC): hwregs-0372 [55] GetRegister : ----Entry hwregs-0585 [56] HwRegisterRead : ----Entry hwregs-0672 [56] HwRegisterRead : ----Exit- AE_OK hwregs-0401 [55] GetRegister : ----Exit- AE_OK hwregs-0432 [55] SetRegister : ----Entry 00000001 hwregs-0585 [56] HwRegisterRead : ----Entry hwregs-0672 [56] HwRegisterRead : ----Exit- AE_OK hwregs-0714 [56] HwRegisterWrite : ----Entry hwregs-0585 [57] HwRegisterRead : ----Entry hwregs-0672 [57] HwRegisterRead : ----Exit- AE_OK hwregs-0840 [56] HwRegisterWrite : ----Exit- AE_OK hwregs-0553 [55] SetRegister : ----Exit- AE_OK ... KDB: enter: manual escape to debugger [thread pid 34 tid 100033] Stopped at 0xc052bb8b = kdb_enter_why+0x3b: movl $0,0xc07915f8 = kdb_why db> where Tracing pid 34 tid 100033 td 0xc4037660 kdb_enter_why(c0719378,c071daab,1,0,1,...) at 0xc052bb8b = kdb_enter_why+0x3b scgetc(c4037660,c3f4acc0,c07910e0,c40aa2b8,c4104200,...) at 0xc049ef16 = scgetc+ 0x486 sckbdevent(c07ae5a0,0,c07b7c00,1,6e8258d2) at 0xc04a200f = sckbdevent+0x8f atkbd_intr(c07ae5a0,0,e461dcf0,c04dfbbd,c07ae5a0,...) at 0xc06bffb5 = atkbd_intr +0x55 atkbdintr(c07ae5a0,0,c0721256,4a1,0,...) at 0xc06c09e1 = atkbdintr+0x21 ithread_loop(c40ffb90,e461dd38,0,0,0,...) at 0xc04dfbbd = ithread_loop+0x12d fork_exit(c04dfa90,c40ffb90,e461dd38) at 0xc04dc22d = fork_exit+0x8d fork_trampoline() at 0xc06da490 = fork_trampoline+0x8 --- trap 0, eip = 0, esp = 0xe461dd70, ebp = 0 --- db > If I try an even more verbose ACPI DEBUG, using the following in /boot/loader.conf, debug.acpi.layer="ACPI_ALL_COMPONENTS" debug.acpi.level="ACPI_LV_FUNCTIONS" I cannot even break to the debugger any more - only ACPI messages are rapidly flashing by, without any chance to capture them. This is on a rather old 800 MHz Athlon machine. Please note that the e-mail address given above is not valid as I have been bitten too often by junk mail. Simply append to the problem report, I'll check back regularly to answer any questions. Following is the dmesg of the standard kernel (without ACPI_DEBUG): Copyright (c) 1992-2009 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.1-RELEASE #0: Sun Jan 4 10:53:24 CET 2009 root@atpcdvvc.xyzzy:/usr/VOL/OBJ/FreeBSD/RELENG_7_1_0_RELEASE/src/sys/XYZZY Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: AMD Athlon(tm) Processor (807.19-MHz 686-class CPU) Origin = "AuthenticAMD" Id = 0x642 Stepping = 2 Features=0x183f9ff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR> AMD Features=0xc0440800<SYSCALL,<b18>,MMX+,3DNow!+,3DNow!> real memory = 1342095360 (1279 MB) avail memory = 1305137152 (1244 MB) cryptosoft0: <software crypto> on motherboard acpi0: <ASUS A7V> on motherboard acpi0: [ITHREAD] acpi0: Power Button (fixed) acpi0: reservation of 0, a0000 (3) failed acpi0: reservation of 100000, 4ff00000 (3) failed Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000 acpi_timer0: <24-bit timer at 3.579545MHz> port 0xe408-0xe40b on acpi0 acpi_button0: <Power Button> on acpi0 pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0 pci0: <ACPI PCI bus> on pcib0 pcib1: <PCI-PCI bridge> at device 1.0 on pci0 pci1: <PCI bus> on pcib1 vgapci0: <VGA-compatible display> mem 0xd6000000-0xd6ffffff,0xd8000000-0xdfffffff irq 11 at device 0.0 on pci1 isab0: <PCI-ISA bridge> at device 4.0 on pci0 isa0: <ISA bus> on isab0 atapci0: <VIA 82C686A UDMA66 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xd800-0xd80f at device 4.1 on pci0 ata0: <ATA channel 0> on atapci0 ata0: [ITHREAD] ata1: <ATA channel 1> on atapci0 ata1: [ITHREAD] uhci0: <VIA 83C572 USB controller> port 0xd400-0xd41f irq 9 at device 4.2 on pci0 uhci0: [GIANT-LOCKED] uhci0: [ITHREAD] usb0: <VIA 83C572 USB controller> on uhci0 usb0: USB revision 1.0 uhub0: <VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1> on usb0 uhub0: 2 ports with 2 removable, self powered uhci1: <VIA 83C572 USB controller> port 0xd000-0xd01f irq 9 at device 4.3 on pci0 uhci1: [GIANT-LOCKED] uhci1: [ITHREAD] usb1: <VIA 83C572 USB controller> on uhci1 usb1: USB revision 1.0 uhub1: <VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1> on usb1 uhub1: 2 ports with 2 removable, self powered viapropm0: <VIA VT82C686A Power Management Unit> port 0xe800-0xe80f at device 4.4 on pci0 smbus0: <System Management Bus> on viapropm0 smb0: <SMBus generic I/O> on smbus0 sis0: <NatSemi DP8381[56] 10/100BaseTX> port 0xa400-0xa4ff mem 0xd5800000-0xd5800fff irq 9 at device 9.0 on pci0 sis0: Silicon Revision: DP83815D miibus0: <MII bus> on sis0 nsphyter0: <DP83815 10/100 media interface> PHY 0 on miibus0 nsphyter0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto sis0: Ethernet address: 00:40:f4:1a:42:ba sis0: [ITHREAD] pcm0: <AudioPCI ES1373-8> port 0xa000-0xa03f irq 5 at device 10.0 on pci0 pcm0: <Cirrus Logic CS4297A AC97 Codec> pcm0: [ITHREAD] pcm0: <Playback: DAC1,DAC2 / Record: ADC> sym0: <810> port 0x9800-0x98ff mem 0xd5000000-0xd50000ff irq 10 at device 11.0 on pci0 sym0: No NVRAM, ID 7, Fast-10, SE, parity checking sym0: [ITHREAD] ral0: <Ralink Technology RT2561S> mem 0xd4800000-0xd4807fff irq 9 at device 13.0 on pci0 ral0: MAC/BBP RT2661B, RF RT2527 ral0: Ethernet address: 00:0e:2e:89:5a:4c ral0: [ITHREAD] atapci1: <Promise PDC20265 UDMA100 controller> port 0x9400-0x9407,0x9000-0x9003,0x8800-0x8807,0x8400-0x8403,0x8000-0x803f mem 0xd4000000-0xd401ffff irq 10 at device 17.0 on pci0 atapci1: [ITHREAD] ata2: <ATA channel 0> on atapci1 ata2: [ITHREAD] ata3: <ATA channel 1> on atapci1 ata3: [ITHREAD] speaker0: <PC speaker> port 0x61 on acpi0 fdc0: <floppy drive controller> port 0x3f2-0x3f5,0x3f7 irq 6 drq 2 on acpi0 fdc0: [FILTER] fd0: <1440-KB 3.5" drive> on fdc0 drive 0 fd1: <1200-KB 5.25" drive> on fdc0 drive 1 sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 sio0: type 16550A sio0: [FILTER] sio1: <16550A-compatible COM port> port 0x2f8-0x2ff irq 3 on acpi0 sio1: type 16550A sio1: [FILTER] 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] psm0: <PS/2 Mouse> irq 12 on atkbdc0 psm0: [GIANT-LOCKED] psm0: [ITHREAD] psm0: model IntelliMouse, device ID 3 cpu0: <ACPI CPU> on acpi0 acpi_throttle0: <ACPI CPU Throttling> on cpu0 pmtimer0 on isa0 orm0: <ISA Option ROMs> at iomem 0xcc000-0xce7ff,0xd0000-0xd07ff pnpid ORM0000 on isa0 ppc0: <Parallel port> at port 0x378-0x37f irq 7 on isa0 ppc0: SMC-like chipset (ECP/EPP/PS2/NIBBLE) in COMPATIBLE mode ppc0: FIFO with 16/16/8 bytes threshold ppbus0: <Parallel port bus> on ppc0 ppbus0: [ITHREAD] ppbus0: IEEE1284 device found /NIBBLE/ECP Probing for PnP devices on ppbus0: ppbus0: <HEWLETT-PACKARD DESKJET 970C> MLC,PCL,PML lpt0: <Printer> on ppbus0 lpt0: Interrupt-driven port ppc0: [GIANT-LOCKED] ppc0: [ITHREAD] sc0: <System console> at flags 0x100 on isa0 sc0: VGA <8 virtual consoles, flags=0x300> vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 ubt0: <vendor 0x0a12 product 0x0001, class 224/1, rev 1.10/3.73, addr 2> on uhub0 ubt0: Interface 0 endpoints: interrupt=0x81, bulk-in=0x82, bulk-out=0x2 ubt0: Interface 1 (alt.config 5) endpoints: isoc-in=0x83, isoc-out=0x3; wMaxPacketSize=49; nframes=6, buffer size=294 ugen0: <THOMSON Speed Touch 330, class 255/0, rev 1.10/4.00, addr 3> on uhub0 uhub2: <ALCOR Generic USB Hub, class 9/0, rev 1.10/1.00, addr 2> on uhub1 uhub2: 4 ports with 4 removable, self powered Timecounter "TSC" frequency 807194618 Hz quality 800 Timecounters tick every 5.000 msec IPsec: Initialized Security Association Processing. ipfw2 (+ipv6) initialized, divert loadable, nat loadable, rule-based forwarding disabled, default to deny, logging disabled ad0: 27199MB <Seagate ST328040A 3.11> at ata0-master UDMA33 acd0: CDRW <PLEXTOR CD-R PX-W1210A/1.10> at ata0-slave PIO4 acd1: DVDR <HL-DT-ST DVDRAM GSA-4163B/A105> at ata1-master UDMA33 ad4: 29188MB <Seagate ST330630A 3.21> at ata2-master UDMA66 ad6: 117800MB <IC35L120AVV207 0 V24OA63A> at ata3-master UDMA100 ad7: 194481MB <Maxtor 6B200P0 BAH41BM0> at ata3-slave UDMA100 Waiting 2 seconds for SCSI devices to settle acd0: FAILURE - INQUIRY ILLEGAL REQUEST asc=0x24 ascq=0x00 acd0: FAILURE - INQUIRY ILLEGAL REQUEST asc=0x24 ascq=0x00 acd1: FAILURE - INQUIRY ILLEGAL REQUEST asc=0x24 ascq=0x00 sks=0x40 0x00 0x01 acd1: FAILURE - INQUIRY ILLEGAL REQUEST asc=0x24 ascq=0x00 sks=0x40 0x00 0x01 GEOM_LABEL: Label for provider ad0s1 is msdosfs/DISK5S1. GEOM_LABEL: Label for provider ad0s2 is msdosfs/DISK5S2. GEOM_LABEL: Label for provider ad4s1 is msdosfs/DISK6S1. GEOM_LABEL: Label for provider ad6s1 is ufs/disk12s1e. GEOM_LABEL: Label for provider ad4s4a is ufs/disk6s4a. GEOM_LABEL: Label for provider ad4s4e is ufs/disk6s4e. sa0 at sym0 bus 0 target 3 lun 0 sa0: <HP HP35480A T503> Removable Sequential Access SCSI-2 device sa0: 3.300MB/s transfers cd0 at ata0 bus 0 target 1 lun 0 cd0: <PLEXTOR CD-R PX-W1210A 1.10> Removable CD-ROM SCSI-0 device cd0: 16.000MB/s transfers cd0: Attempt to query device size failed: NOT READY, Medium not present - tray closed cd1 at ata1 bus 0 target 0 lun 0 cd1: <HL-DT-ST DVDRAM GSA-4163B A105> Removable CD-ROM SCSI-0 device cd1: 33.000MB/s transfers cd1: Attempt to query device size failed: NOT READY, Medium not present Trying to mount root from ufs:/dev/ad0s3a ubt0: at uhub0 port 1 (addr 2) disconnected ubt0: detached ubt0: <vendor 0x0a12 product 0x0001, class 224/1, rev 1.10/3.73, addr 2> on uhub0 ubt0: Interface 0 endpoints: interrupt=0x81, bulk-in=0x82, bulk-out=0x2 ubt0: Interface 1 (alt.config 5) endpoints: isoc-in=0x83, isoc-out=0x3; wMaxPacketSize=49; nframes=6, buffer size=294 GEOM_LABEL: Label ufs/disk6s4a removed. GEOM_LABEL: Label for provider ad4s4a is ufs/disk6s4a. GEOM_LABEL: Label ufs/disk12s1e removed. GEOM_LABEL: Label for provider ad6s1 is ufs/disk12s1e. GEOM_LABEL: Label ufs/disk6s4e removed. GEOM_LABEL: Label for provider ad4s4e is ufs/disk6s4e. GEOM_LABEL: Label ufs/disk6s4a removed. GEOM_LABEL: Label ufs/disk6s4e removed. GEOM_LABEL: Label ufs/disk12s1e removed. tap0: Ethernet address: 00:bd:57:05:00:00 ieee80211_load_module: load the wlan_scan_ap module by hand for now. sis0: Applying short cable fix (reg=f5) sis0: Applying short cable fix (reg=f5) WARNING: attempt to net_add_domain(bluetooth) after domainfinalize() WARNING: attempt to net_add_domain(netgraph) after domainfinalize() >How-To-Repeat: See above. >Fix: Currently unknown. >Release-Note: >Audit-Trail: >Unformatted:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200901180949.n0I9nGuu007252>