From owner-freebsd-bugs@FreeBSD.ORG Sun Jan 18 10:20:02 2009 Return-Path: Delivered-To: freebsd-bugs@hub.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 32408106564A for ; Sun, 18 Jan 2009 10:20:02 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [IPv6:2001:4f8:fff6::28]) by mx1.freebsd.org (Postfix) with ESMTP id 01F648FC08 for ; Sun, 18 Jan 2009 10:20:02 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) by freefall.freebsd.org (8.14.3/8.14.3) with ESMTP id n0IAK0Xx052027 for ; Sun, 18 Jan 2009 10:20:00 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.14.3/8.14.3/Submit) id n0IAK0dE052026; Sun, 18 Jan 2009 10:20:00 GMT (envelope-from gnats) Resent-Date: Sun, 18 Jan 2009 10:20:00 GMT Resent-Message-Id: <200901181020.n0IAK0dE052026@freefall.freebsd.org> Resent-From: FreeBSD-gnats-submit@FreeBSD.org (GNATS Filer) Resent-To: freebsd-bugs@FreeBSD.org Resent-Reply-To: FreeBSD-gnats-submit@FreeBSD.org, Martin Birgmeier Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 9D000106564A for ; Sun, 18 Jan 2009 10:16:02 +0000 (UTC) (envelope-from martin@email.aon.at) Received: from email.aon.at (nat-warsl417-01.aon.at [195.3.96.119]) by mx1.freebsd.org (Postfix) with ESMTP id 670AB8FC1C for ; Sun, 18 Jan 2009 10:16:01 +0000 (UTC) (envelope-from martin@email.aon.at) Received: (qmail 24506 invoked from network); 18 Jan 2009 09:49:19 -0000 Received: from smarthub92.highway.telekom.at (HELO email.aon.at) ([172.18.5.231]) (envelope-sender ) by fallback43.highway.telekom.at (qmail-ldap-1.03) with SMTP for ; 18 Jan 2009 09:49:19 -0000 Received: (qmail 2352 invoked from network); 18 Jan 2009 09:49:17 -0000 Received: from 80-121-63-200.adsl.highway.telekom.at (HELO gandalf.xyzzy) ([80.121.63.200]) (envelope-sender ) by smarthub92.highway.telekom.at (qmail-ldap-1.03) with SMTP for ; 18 Jan 2009 09:49:16 -0000 Received: from gandalf.xyzzy (localhost.xyzzy [127.0.0.1]) by gandalf.xyzzy (8.14.3/8.14.3) with ESMTP id n0I9nGWc007253 for ; Sun, 18 Jan 2009 10:49:16 +0100 (CET) (envelope-from martin@gandalf.xyzzy) Received: (from martin@localhost) by gandalf.xyzzy (8.14.3/8.14.3/Submit) id n0I9nGuu007252; Sun, 18 Jan 2009 10:49:16 +0100 (CET) (envelope-from martin) Message-Id: <200901180949.n0I9nGuu007252@gandalf.xyzzy> Date: Sun, 18 Jan 2009 10:49:16 +0100 (CET) From: Martin Birgmeier To: FreeBSD-gnats-submit@FreeBSD.org X-Send-Pr-Version: 3.113 Cc: Subject: kern/130683: shutdown hangs after syncing disks - ACPI race? X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list Reply-To: Martin Birgmeier List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 18 Jan 2009 10:20:02 -0000 >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 AMD Features=0xc0440800,MMX+,3DNow!+,3DNow!> real memory = 1342095360 (1279 MB) avail memory = 1305137152 (1244 MB) cryptosoft0: on motherboard acpi0: 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: on acpi0 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 pcib1: at device 1.0 on pci0 pci1: on pcib1 vgapci0: mem 0xd6000000-0xd6ffffff,0xd8000000-0xdfffffff irq 11 at device 0.0 on pci1 isab0: at device 4.0 on pci0 isa0: on isab0 atapci0: port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xd800-0xd80f at device 4.1 on pci0 ata0: on atapci0 ata0: [ITHREAD] ata1: on atapci0 ata1: [ITHREAD] uhci0: port 0xd400-0xd41f irq 9 at device 4.2 on pci0 uhci0: [GIANT-LOCKED] uhci0: [ITHREAD] usb0: on uhci0 usb0: USB revision 1.0 uhub0: on usb0 uhub0: 2 ports with 2 removable, self powered uhci1: port 0xd000-0xd01f irq 9 at device 4.3 on pci0 uhci1: [GIANT-LOCKED] uhci1: [ITHREAD] usb1: on uhci1 usb1: USB revision 1.0 uhub1: on usb1 uhub1: 2 ports with 2 removable, self powered viapropm0: port 0xe800-0xe80f at device 4.4 on pci0 smbus0: on viapropm0 smb0: on smbus0 sis0: port 0xa400-0xa4ff mem 0xd5800000-0xd5800fff irq 9 at device 9.0 on pci0 sis0: Silicon Revision: DP83815D miibus0: on sis0 nsphyter0: PHY 0 on miibus0 nsphyter0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto sis0: Ethernet address: 00:40:f4:1a:42:ba sis0: [ITHREAD] pcm0: port 0xa000-0xa03f irq 5 at device 10.0 on pci0 pcm0: pcm0: [ITHREAD] pcm0: 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: 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: 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: on atapci1 ata2: [ITHREAD] ata3: on atapci1 ata3: [ITHREAD] speaker0: port 0x61 on acpi0 fdc0: 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: port 0x60,0x64 irq 1 on acpi0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] atkbd0: [ITHREAD] psm0: irq 12 on atkbdc0 psm0: [GIANT-LOCKED] psm0: [ITHREAD] psm0: model IntelliMouse, device ID 3 cpu0: on acpi0 acpi_throttle0: on cpu0 pmtimer0 on isa0 orm0: at iomem 0xcc000-0xce7ff,0xd0000-0xd07ff pnpid ORM0000 on isa0 ppc0: 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: on ppc0 ppbus0: [ITHREAD] ppbus0: IEEE1284 device found /NIBBLE/ECP Probing for PnP devices on ppbus0: ppbus0: MLC,PCL,PML lpt0: on ppbus0 lpt0: Interrupt-driven port ppc0: [GIANT-LOCKED] ppc0: [ITHREAD] sc0: at flags 0x100 on isa0 sc0: VGA <8 virtual consoles, flags=0x300> vga0: at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 ubt0: 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: on uhub0 uhub2: 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 at ata0-master UDMA33 acd0: CDRW at ata0-slave PIO4 acd1: DVDR at ata1-master UDMA33 ad4: 29188MB at ata2-master UDMA66 ad6: 117800MB at ata3-master UDMA100 ad7: 194481MB 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: Removable Sequential Access SCSI-2 device sa0: 3.300MB/s transfers cd0 at ata0 bus 0 target 1 lun 0 cd0: 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: 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: 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: