kern/46437: panic: ahci_exec_command: polled command not done

[riz%NetBSD.org@localhost]

>Number:         46437
>Category:       kern
>Synopsis:       panic: ahci_exec_command: polled command not done
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed May 09 16:25:00 +0000 2012
>Originator:     Jeff Rizzo
>Release:        6.0_BETA
>Organization:
>Environment:
NetBSD xenserver1.boogers.sf.ca.us 6.0_BETA NetBSD 6.0_BETA (XEN3_DOM0) amd64

>Description:
About every second or third reboot of my xen dom0 box, when shutting down, it 
panics thus:

syncing disks... 5 done
unmounting file systems... done        
Skipping crash dump on recursive panic 
panic: ahci_exec_command: polled command not done     
cpu0: Begin traceback...
printf_nolog() at netbsd:printf_nolog  
ahci_probe_drive() at netbsd:ahci_probe_drive
wd_flushcache() at netbsd:wd_flushcache+0xd7
wd_shutdown() at netbsd:wd_shutdown+0x3e
pmf_system_shutdown() at netbsd:pmf_system_shutdown+0x81
cpu_reboot() at netbsd:cpu_reboot+0x2b 
sys_reboot() at netbsd:sys_reboot+0x73 
syscall() at netbsd:syscall+0xc4
cpu0: End traceback...  
fatal breakpoint trap in supervisor mode
trap type 1 code 0 rip ffffffff80224295 cs e030 rflags 246 cr2  7f7ff7fd3000 cpl
 8 rsp ffffa0000e4f38e0 
Stopped in pid 72.1 (reboot) at netbsd:breakpoint+0x5:  leave  
breakpoint() at netbsd:breakpoint+0x5  
vpanic() at netbsd:vpanic+0x1f2
printf_nolog() at netbsd:printf_nolog
ahci_probe_drive() at netbsd:ahci_probe_drive
wd_flushcache() at netbsd:wd_flushcache+0xd7
wd_shutdown() at netbsd:wd_shutdown+0x3e
pmf_system_shutdown() at netbsd:pmf_system_shutdown+0x81
cpu_reboot() at netbsd:cpu_reboot+0x2b
sys_reboot() at netbsd:sys_reboot+0x73
syscall() at netbsd:syscall+0xc4
ds          1ea0
es          3920
fs          100
gs          8200
rdi         8   
rsi         1   
rbp         ffffa0000e4f38e0
rbx         4   
rdx         0   
rcx         8   
rax         0
r8          ffffffff80c04e80    cpu_info_primary
r9          1
r10         0
r11         ffffffff80f3d8be
r12         ffffffff80a978b0    __link_set_malloc_types_sym_M_XDATA+0x3148
r13         ffffa0000e4f3920
r14         ffffa00000b81ea0
r15         ffffa00001757a68
rip         ffffffff80224295    breakpoint+0x5
cs          e030
rflags      246
rsp         ffffa0000e4f38e0
ss          e02b
netbsd:breakpoint+0x5:  leave
db>


Full dmesg of the affected system is as follows:

Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007, 2008, 2009, 2010, 2011, 2012
    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 6.0_BETA (XEN3_DOM0)
total memory = 256 MB
avail memory = 232 MB
timecounter: Timecounters tick every 10.000 msec
mainbus0 (root)
cpu0 at mainbus0 apid 0
cpu1 at mainbus0 apid 2
cpu2 at mainbus0 apid 4
cpu3 at mainbus0 apid 6
ioapic0 at mainbus0 apid 0: pa 0xfec00000, version 20, 24 pins
hypervisor0 at mainbus0: Xen version 4.1
VIRQ_DEBUG interrupt using event channel 1
vcpu0 at hypervisor0: Intel(R) Core(TM) i5-2400 CPU @ 3.10GHz, id 0x206a7
xenbus0 at hypervisor0: Xen Virtual Bus Interface
xencons0 at hypervisor0: Xen Virtual Console Driver
xencons0: console major 143, unit 0
xencons0: using event channel 2
acpi0 at hypervisor0: Intel ACPICA 20110623
acpi0: X/RSDT: OemId <ALASKA,   A M I,01072009>, AslId <AMI ,00010013>
ACPI Error: [RAMB] Namespace lookup failure, AE_NOT_FOUND (20110623/psargs-392)
ACPI Exception: AE_NOT_FOUND, Could not execute arguments for [RAMW] (Region) 
(20110623/nsinit-380)
acpi0: SCI interrupting at int 9
timecounter: Timecounter "ACPI-Safe" frequency 3579545 Hz quality 900
MCH (PNP0C01) at acpi0 not configured
SIO1 (PNP0C02) at acpi0 not configured
TMR (PNP0100) at acpi0 not configured
pcppi0 at acpi0 (SPKR, PNP0800): io 0x61
RMSC (PNP0C02) at acpi0 not configured
UAR1 (PNP0501) at acpi0 not configured
PCH (PNP0C01) at acpi0 not configured
CWDT (INT3F0D) at acpi0 not configured
HPET (PNP0103) at acpi0 not configured
acpibut0 at acpi0 (PWRB, PNP0C0C-170): ACPI Power Button
RMEM (PNP0C01) at acpi0 not configured
OMSC (PNP0C02) at acpi0 not configured
AMW0 (PNP0C14) at acpi0 not configured
pci0 at hypervisor0 bus 0: configuration mode 1
pci0: i/o space, memory space enabled
pchb0 at pci0 dev 0 function 0: vendor 0x8086 product 0x0100 (rev. 0x09)
ppb0 at pci0 dev 1 function 0: vendor 0x8086 product 0x0101 (rev. 0x09)
ppb0: PCI Express 2.0 <Root Port of PCI-E Root Complex>
pci1 at ppb0 bus 1
pci1: i/o space, memory space enabled
vga0 at pci0 dev 2 function 0: vendor 0x8086 product 0x0102 (rev. 0x09)
wsdisplay0 at vga0 kbdmux 1
wsmux1: connecting to wsdisplay0
drm at vga0 not configured
vendor 0x8086 product 0x1c3a (miscellaneous communications, revision 0x04) at 
pci0 dev 22 function 0 not configured
ehci0 at pci0 dev 26 function 0: vendor 0x8086 product 0x1c2d (rev. 0x05)
ehci0: interrupting at ioapic0 pin 23, event channel 4
ehci0: BIOS has given up ownership
ehci0: EHCI version 1.0
usb0 at ehci0: USB revision 2.0
hdaudio0 at pci0 dev 27 function 0: HD Audio Controller
hdaudio0: interrupting at ioapic0 pin 22, event channel 5
hdafg0 at hdaudio0: Realtek ALC892
hdafg0: DAC00 8ch: Speaker [Jack]
hdafg0: DAC01 2ch: HP Out [Jack]
hdafg0: DIG02 2ch: SPDIF Out [Jack]
hdafg0: DIG03 2ch: SPDIF Out [Built-In]
hdafg0: ADC04 2ch: Line In [Jack], Mic In [Jack]
hdafg0: ADC05 2ch: Mic In [Jack]
hdafg0: 8ch/2ch 32000Hz 44100Hz 48000Hz 88200Hz 96000Hz 192000Hz PCM16 PCM20 
PCM24 AC3
audio0 at hdafg0: full duplex, playback, capture, independent
hdafg1 at hdaudio0: Intel product 2805
hdafg1: DP00 8ch: Digital Out [Jack]
hdafg1: 8ch/0ch 48000Hz PCM16*
ppb1 at pci0 dev 28 function 0: vendor 0x8086 product 0x1c10 (rev. 0xb5)
ppb1: PCI Express 2.0 <Root Port of PCI-E Root Complex>
pci2 at ppb1 bus 2
pci2: i/o space, memory space enabled
ppb2 at pci0 dev 28 function 4: vendor 0x8086 product 0x1c18 (rev. 0xb5)
ppb2: PCI Express 2.0 <Root Port of PCI-E Root Complex>
pci3 at ppb2 bus 3
pci3: i/o space, memory space enabled
pciide0 at pci3 dev 0 function 0: vendor 0x1106 product 0x0415 (rev. 0x00)
pciide0: bus-master DMA support present, but unused (no driver support)
pciide0: primary channel wired to native-PCI mode
pciide0: using ioapic0 pin 16, event channel 6 for native-PCI interrupt
atabus0 at pciide0 channel 0
pciide0: secondary channel wired to native-PCI mode
atabus1 at pciide0 channel 1
ppb3 at pci0 dev 28 function 5: vendor 0x8086 product 0x1c1a (rev. 0xb5)
ppb3: PCI Express 2.0 <Root Port of PCI-E Root Complex>
pci4 at ppb3 bus 4
pci4: i/o space, memory space enabled
vendor 0x1b21 product 0x1042 (USB serial bus, interface 0x30) at pci4 dev 0 
function 0 not configured
ppb4 at pci0 dev 28 function 6: vendor 0x8086 product 0x1c1c (rev. 0xb5)
ppb4: PCI Express 2.0 <Root Port of PCI-E Root Complex>
pci5 at ppb4 bus 5
pci5: i/o space, memory space enabled
re0 at pci5 dev 0 function 0: RealTek 8168/8111 PCIe Gigabit Ethernet (rev. 
0x06)
re0: interrupting at ioapic0 pin 18, event channel 7
re0: Ethernet address bc:ae:c5:de:7f:d4
re0: using 256 tx descriptors
rgephy0 at re0 phy 7: RTL8169S/8110S/8211 1000BASE-T media interface, rev. 4
rgephy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 
1000baseT-FDX, auto
ppb5 at pci0 dev 28 function 7: vendor 0x8086 product 0x244e (rev. 0xb5)
ppb5: PCI Express 2.0 <Root Port of PCI-E Root Complex>
pci6 at ppb5 bus 6
pci6: i/o space, memory space enabled
ppb6 at pci6 dev 0 function 0: vendor 0x1b21 product 0x1080 (rev. 0x01)
pci7 at ppb6 bus 7
pci7: i/o space, memory space enabled
ehci1 at pci0 dev 29 function 0: vendor 0x8086 product 0x1c26 (rev. 0x05)
ehci1: interrupting at ioapic0 pin 23, event channel 4
ehci1: BIOS has given up ownership
ehci1: EHCI version 1.0
usb1 at ehci1: USB revision 2.0
ichlpcib0 at pci0 dev 31 function 0: vendor 0x8086 product 0x1c4a (rev. 0x05)
timecounter: Timecounter "ichlpcib0" frequency 3579545 Hz quality 1000
ichlpcib0: 24-bit timer
ichlpcib0: TCO (watchdog) timer configured.
ahcisata0 at pci0 dev 31 function 2: vendor 0x8086 product 0x1c02 (rev. 0x05)
ahcisata0: interrupting at ioapic0 pin 20, event channel 8
ahcisata0: 64-bit DMA
ahcisata0: AHCI revision 1.30, 6 ports, 32 slots, CAP 
0xe730ff45<EMS,PSC,SSC,PMD,ISS=0x3=Gen3,SCLO,SAL,SALP,SSNTF,SNCQ,S64A>
atabus2 at ahcisata0 channel 1
atabus3 at ahcisata0 channel 2
atabus4 at ahcisata0 channel 3
vendor 0x8086 product 0x1c22 (SMBus serial bus, revision 0x05) at pci0 dev 31 
function 3 not configured
isa0 at ichlpcib0
pckbc0 at isa0 port 0x60-0x64
timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
timecounter: Timecounter "xen_system_time" frequency 1000000000 Hz quality 10000
Xen clock: using event channel 9
xenbus0: using event channel 10
atapibus0 at atabus0: 2 targets
uhub0 at usb0: vendor 0x8086 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhub1 at usb1: vendor 0x8086 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
cd0 at atapibus0 drive 0: <CD-RW  52X24, , K.DC> cdrom removable
cd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 2 (Ultra/33)
ahcisata0 port 1: device present, speed: 3.0Gb/s
ahcisata0 port 2: device present, speed: 1.5Gb/s
ahcisata0 port 3: device present, speed: 1.5Gb/s
wd0 at atabus2 drive 0
wd0: <WDC WD2500JS-41SGB0>
wd0: drive supports 16-sector PIO transfers, LBA48 addressing
wd0: 232 GB, 484521 cyl, 16 head, 63 sec, 512 bytes/sect x 488397168 sectors
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133)
wd0(ahcisata0:1:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) 
(using DMA)
wd1 at atabus3 drive 0
wd1: <WDC WD10EACS-00C7B0>
wd1: drive supports 16-sector PIO transfers, LBA48 addressing
wd1: 931 GB, 1938021 cyl, 16 head, 63 sec, 512 bytes/sect x 1953525168 sectors
wd1: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133)
wd1(ahcisata0:2:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) 
(using DMA)
wd2 at atabus4 drive 0
wd2: <WDC WD10EACS-00C7B0>
wd2: drive supports 16-sector PIO transfers, LBA48 addressing
wd2: 931 GB, 1938021 cyl, 16 head, 63 sec, 512 bytes/sect x 1953525168 sectors
wd2: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133)
wd2(ahcisata0:3:0): using PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133) 
(using DMA)
uhub2 at uhub0 port 1: vendor 0x8087 product 0x0024, class 9/0, rev 2.00/0.00, 
addr 2
uhub2: single transaction translator
uhub3 at uhub1 port 1: vendor 0x8087 product 0x0024, class 9/0, rev 2.00/0.00, 
addr 2
uhub3: single transaction translator
uhub2: 6 ports with 6 removable, self powered
uhub3: 8 ports with 8 removable, self powered
Kernelized RAIDframe activated
raid0: RAID Level 1
raid0: Components: /dev/wd1e /dev/wd2e
raid0: Total Sectors: 1953524992 (953869 MB)
boot device: raid0
root on raid0a dumps on raid0b
Your machine does not initialize mem_clusters; sparse_dumps disabled
root file system type: ffs
wsdisplay0: screen 0 added (80x25, vt100 emulation)
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)
balloon0 at xenbus0 id 0: Xen Balloon driver
balloon0: current reservation: 262144 KiB
balloon0: current reservation: 65536 pages => target: 65536 pages

>How-To-Repeat:
Reboot the system with 'shutdown -r now'.  Sometimes it panics, sometimes not.
>Fix:
None given.