Re: Tracking down ata0 reset hang

> From: Jesse Guardiani <jesse_at_wingnet.net>
> Date: Mon, 22 Dec 2003 17:31:34 -0500
> Sender: owner-freebsd-current_at_freebsd.org
> 
> Jesse Guardiani wrote:

> I found something interesting out today. If I boot with 'boot -v -D' then
> I can successfully suspend and resume with APM.
> 
> If I boot with either 'boot -v' or 'boot -D' alone, I cannot!
> 
> Here's the verbose suspend/resume cycle:
> 
> Lock GEOM topology not exclusively locked _at_ ../../.
> ./geom/geom_subr.c:261
> acd0: WARNING - removed from configuration
> pcib2: device pccard0 requested decoded I/O range 0x3e8-0x3ef
> sio4: detached
> pci_cfgintr_valid: BIOS irq 9 is valid
> pci_cfgintr: 0:29 INTA BIOS irq 9
> pci_cfgintr_valid: BIOS irq 11 is valid
> pci_cfgintr: 0:29 INTB BIOS irq 11
> pci_cfgintr_valid: BIOS irq 9 is valid
> pci_cfgintr: 0:29 INTC BIOS irq 9
> pci_cfgintr_valid: BIOS irq 5 is valid
> pci_cfgintr: 0:31 INTB BIOS irq 5
> pci_cfgintr_valid: BIOS irq 5 is valid
> pci_cfgintr: 0:31 INTB BIOS irq 5
> pci_cfgintr_valid: BIOS irq 5 is valid
> pci_cfgintr: 0:31 INTB BIOS irq 5
> pci_cfgintr_valid: BIOS irq 9 is valid
> pci_cfgintr: 1:0 INTA BIOS irq 9
> pci_cfgintr_valid: BIOS irq 9 is valid
> pci_cfgintr: 2:0 INTA BIOS irq 9
> pci_cfgintr_valid: BIOS irq 5 is valid
> pci_cfgintr: 2:0 INTB BIOS irq 5
> pci_cfgintr_valid: BIOS irq 9 is valid
> pci_cfgintr: 2:0 INTC BIOS irq 9
> pci_cfgintr_valid: BIOS irq 9 is valid
> pci_cfgintr: 2:2 INTA BIOS irq 9
> pci_cfgintr_valid: BIOS irq 10 is valid
> pci_cfgintr: 2:8 INTA BIOS irq 10
> atkbd: the current kbd controller command byte 0047
> atkbd: keyboard ID 0x54ab (2)
> ata0: resetting devices ..
> ata0: reset tp1 mask=03 ostat0=50 ostat1=00
> ad0: stat=0x50 err=0x01 lsb=0x00 msb=0x00
> ata0-slave:  stat=0x00 err=0x01 lsb=0x00 msb=0x00
> ata0: reset tp2 mask=03 stat0=50 stat1=00 devices=0x1<ATA_MASTER>
> ad0: pio=0x0c wdma=0x22 udma=0x45 cable=80pin
> ad0: setting PIO4 on Intel ICH3 chip
> 
> <hangs here normally>
> 
> 
> ad0: setting UDMA100 on Intel ICH3 chip
> ad0: setting UDMA100 on Intel ICH3 chip
> done
> start (88000000) < sc->membase (c0200000)
> end (ffffffff) > sc->memlimit (cfffffff)
> start (88000000) < sc->pmembase (e8000000)
> end (ffffffff) > sc->pmemlimit (cfffffff)
> pcib2: device pccard0 requested decoded memory range 0x88000000-0xffffffff
> pccard0: CIS version PC Card Standard 5.0
> pccard0: CIS info: 3Com Megahertz, 3CXM756/3CCM756
> pccard0: Manufacturer code 0x101, product 0x3f
> pccard0: function 0: serial port, ccr addr 300 mask 17
> pccard0: function 0, config table entry 32: I/O card; irq mask ffff; iomask a, i
> ospace 3f8-3ff; rdybsy_active io8 irqlevel powerdown audio
> pccard0: function 0, config table entry 33: I/O card; irq mask ffff; iomask a, i
> ospace 2f8-2ff; rdybsy_active io8 irqlevel powerdown audio
> pccard0: function 0, config table entry 34: I/O card; irq mask ffff; iomask a, i
> ospace 3e8-3ef; rdybsy_active io8 irqlevel powerdown audio
> pccard0: function 0, config table entry 35: I/O card; irq mask ffff; iomask a, i
> ospace 2e8-2ef; rdybsy_active io8 irqlevel powerdown audio
> pcib2: device pccard0 requested decoded I/O range 0x3f8-0x3ff
> pccard0: Allocation failed for cfe 32
> pcib2: device pccard0 requested decoded I/O range 0x2f8-0x2ff
> pccard0: Allocation failed for cfe 33
> pcib2: device pccard0 requested decoded I/O range 0x3e8-0x3ef
> start (88000000) < sc->membase (c0200000)
> end (ffffffff) > sc->memlimit (cfffffff)
> start (88000000) < sc->pmembase (e8000000)
> end (ffffffff) > sc->pmemlimit (cfffffff)
> pcib2: device pccard0 requested decoded memory range 0x88000000-0xffffffff
> sio4: <3Com Megahertz 3CXM756/3CCM756> at port 0x3e8-0x3ef irq 9 function 0 conf
> ig 34 on pccard0
> pcib2: device sio4 requested decoded I/O range 0x3e8-0x3ef
> pcib2: device pccard0 requested decoded I/O range 0x3e8-0x3ef
> pcib2: device sio4 requested decoded I/O range 0x3e8-0x3ef
> sio4: type 16550A
> sio4: unable to activate interrupt in fast mode - using normal mode
> ata1: reset tp1 mask=03 ostat0=50 ostat1=00
> ata1-master: stat=0x00 err=0x01 lsb=0x14 msb=0xeb
> ata1-slave:  stat=0x00 err=0x01 lsb=0x14 msb=0xeb
> ata1: reset tp2 mask=03 stat0=00 stat1=00 devices=0xc<ATAPI_SLAVE,ATAPI_MASTER>
> ata1: [MPSAFE]
> Dec 22 13:59:25 trevarthan kernel: wakeup from sleeping state (slept 00:00:13)
> Dec 22 13:59:25 trevarthan kernel: kbdc: RESET_KBD return code:00fa
> Dec 22 13:59:25 trevarthan kernel: kbdc: RESET_KBD status:00aa
> Dec 22 13:59:25 trevarthan kernel: stray irq15
> ata1-master: pio=0x0c wdma=0x22 udma=0x42 cable=40pin
> ata1-master: setting PIO4 on Intel ICH3 chip
> ata1-master: setting UDMA33 on Intel ICH3 chip
> acd0: <HL-DT-STDVD-ROM GDR8081N/0011> DVDROM drive at ata1 as master
> acd0: read 1722KB/s (4134KB/s), 512KB buffer, UDMA33
> acd0: Reads: CDR, CDRW, CDDA stream, DVDROM, DVDR, DVDRAM, packet
> acd0: Writes:
> acd0: Audio: play, 256 volume levels
> acd0: Mechanism: ejectable tray, unlocked
> acd0: Medium: 120mm data disc
> 
> 
> Pretty darn wierd. Anyone have any ideas as to why it works when the serial
> console AND verbose boot is enabled?

I can confirm this on my system, as well. And I do have an explanation
(but a fix will probably have to come from Søren.

The reason is almost certainly a timing issue. When you boot -v, the
resume sends a LOT more data to the screen and when you use -D, it sends
it to both the screen and the serial port which is MUCH slower to
complete than the screen. This allows SOMETHING to clear or complete or
something on resume and all is well.

Hopefully this will give Søren an idea of where to look.
-- 
R. Kevin Oberman, Network Engineer
Energy Sciences Network (ESnet)
Ernest O. Lawrence Berkeley National Laboratory (Berkeley Lab)
E-mail: oberman_at_es.net			Phone: +1 510 486-8634