Subject: Strange 30-second pause with atabus1 on APM resume under NetBSD
To: None <netbsd-users@netbsd.org>
From: Brian de Alwis <bsd@cs.ubc.ca>
List: netbsd-users
Date: 11/10/2005 11:47:04
One unwelcome change noticed since upgrading to 3.0_BETA on my
laptop is a 30-second pause when resuming from suspend.  This didn't
happen previously under 2.x.

Following is an extract from my /var/log/messages with ATADEBUG
and atadebug_mask=0xFFFF upon resuming.  You can see the 30-second
wait for atabus1 -- but I don't have anything on atabus1!  I'm not
sure why atabus0 and atabus1 have different things happening either.
(Note: I stuck the "resuming done" printfs to see completion.)

Nov 10 11:17:35 slab /netbsd: atabus0: resuming...
Nov 10 11:17:35 slab /netbsd: piixide0:0:0: after reset, sc=0x1 sn=0x1 cl=0x0 ch=0x0
Nov 10 11:17:35 slab /netbsd: piixide0:0:1: after reset, sc=0x0 sn=0x0 cl=0x0 ch=0x0
Nov 10 11:17:35 slab /netbsd: piixide0:0: wdcwait_reset() end, st0=0x50 st1=0x0
Nov 10 11:17:35 slab /netbsd: atabus0: resuming done
Nov 10 11:17:35 slab /netbsd: atabus1: resuming...
Nov 10 11:17:47 slab /netbsd: ata_exec_xfer 0xc098b000 channel 0 drive 0
Nov 10 11:17:49 slab /netbsd: atastart from ata_exec_xfer, flags 0x0
Nov 10 11:17:49 slab /netbsd: atastart: xfer 0xc098b000 channel 0 drive 0
Nov 10 11:17:49 slab /netbsd: wdccommandshort piixide0:0:0 command 0x10
Nov 10 11:17:49 slab /netbsd: __wdcwait: timeout (time=11), status d0 error d0 (mask 0x40 bits 0x40)
Nov 10 11:17:49 slab last message repeated 154 times
Nov 10 11:17:49 slab /netbsd: wdccommand piixide0:0:0: command=0xef cylin=0 head=0 sector=0 count=12 features=3
Nov 10 11:17:49 slab /netbsd: __wdcwait: timeout (time=11), status d0 error d0 (mask 0x40 bits 0x40)
Nov 10 11:17:49 slab last message repeated 20 times
Nov 10 11:17:49 slab /netbsd: wdccommand piixide0:0:0: command=0xef cylin=0 head=0 sector=0 count=66 features=3
Nov 10 11:17:49 slab /netbsd: __wdcwait: timeout (time=11), status d0 error d0 (mask 0x40 bits 0x40)
Nov 10 11:17:49 slab /netbsd: __wdcwait: timeout (time=11), status d0 error d0 (mask 0x40 bits 0x40)
Nov 10 11:17:49 slab /netbsd: wdccommand piixide0:0:0: command=0xc6 cylin=0 head=0 sector=0 count=16 features=0
Nov 10 11:17:49 slab /netbsd: __wdcwait: did busy-wait, time=2
Nov 10 11:17:49 slab /netbsd: wdccommand piixide0:0:0: command=0xca cylin=39677 head=64 sector=238 count=16 features=0
Nov 10 11:17:57 slab /netbsd: ata_exec_xfer 0xc098b000 channel 0 drive 0
Nov 10 11:17:57 slab /netbsd: atastart from ata_exec_xfer, flags 0x0
Nov 10 11:17:57 slab /netbsd: atastart: xfer 0xc098b000 channel 0 drive 0
Nov 10 11:17:57 slab /netbsd: wdccommand piixide0:0:0: command=0xca cylin=39614 head=64 sector=62 count=16 features=0
Nov 10 11:18:06 slab /netbsd: piixide0:1:0: after reset, sc=0x0 sn=0x0 cl=0x0 ch=0x0
Nov 10 11:18:06 slab /netbsd: piixide0:1:1: after reset, sc=0x0 sn=0x0 cl=0x0 ch=0x0
Nov 10 11:18:06 slab /netbsd: piixide0:1: wdcwait_reset() end, st0=0x0 st1=0x0
Nov 10 11:18:08 slab /netbsd: atabus1: resuming done

My dmesg with atadebug_mask = DEBUG_PROBE | DEBUG_DETACH:

    pcib0 at pci0 dev 7 function 0
    pcib0: Intel 82371AB (PIIX4) PCI-ISA Bridge (rev. 0x02)
    piixide0 at pci0 dev 7 function 1
    piixide0: Intel 82371AB IDE controller (PIIX4) (rev. 0x01)
    piixide0: bus-master DMA support present
    piixide0: primary channel wired to compatibility mode
    piixide0: primary channel interrupting at irq 14
    atabus0 at piixide0 channel 0
    piixide0: secondary channel wired to compatibility mode
    piixide0: secondary channel interrupting at irq 15
    atabus1 at piixide0 channel 1
    [...]
    apm0 at mainbus0: Power Management spec V1.2
    piixide0:0: before reset, st0=0x50, st1=0x0
    piixide0:1: before reset, st0=0x0, st1=0x0
    piixide0:1 drive 0 wd_cyl_lo: got 0x0 != 0x02
    piixide0:1 drive 0 wd_cyl_lo: got 0x0 != 0x01
    piixide0:1 drive 0 wd_sector: got 0x0 != 0x01
    piixide0:1 drive 0 wd_sector: got 0x0 != 0x02
    piixide0:1 drive 0 wd_cyl_lo(2): got 0x0 != 0x01
    piixide0:1 drive 1 wd_cyl_lo: got 0x0 != 0x02
    piixide0:1 drive 1 wd_cyl_lo: got 0x0 != 0x01
    piixide0:1 drive 1 wd_sector: got 0x0 != 0x01
    piixide0:1 drive 1 wd_sector: got 0x0 != 0x02
    piixide0:1 drive 1 wd_cyl_lo(2): got 0x0 != 0x01
    atabusattach: ch_drive_flags 0x0 0x0
    piixide0:0:0: after reset, sc=0x1 sn=0x1 cl=0x0 ch=0x0
    piixide0:0:1: after reset, sc=0x1 sn=0x1 cl=0x0 ch=0x0
    piixide0:0: wdcwait_reset() end, st0=0x50 st1=0x0
    piixide0:0: after reset, ret_value=0x3
    piixide0:0:0: after reset, sc=0x1 sn=0x1 cl=0x0 ch=0x0
    piixide0:0:1: after reset, sc=0x1 sn=0x1 cl=0x0 ch=0x0
    piixide0:0: wait DRDY st0 0x50 st1 0x0
    atabusattach: ch_drive_flags 0x1 0x0
    wd0 at atabus0 drive 0: <FUJITSU MHT2040AT>
    wd0: drive supports 16-sector PIO transfers, LBA addressing
    wd0: 38154 MB, 77520 cyl, 16 head, 63 sec, 512 bytes/sect x 78140160 sectors
    wd0: 32-bit data port
    wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 5 (Ultra/100)
    wd0(piixide0:0:0): using PIO mode 4, Ultra-DMA mode 2 (Ultra/33) (using DMA)
    __wdcwait: timeout (time=11), status d0 error d0 (mask 0x40 bits 0x40)
    [repeated 29 times]
    boot device: wd0
    root on wd0a dumps on wd0b
    __wdcwait: timeout (time=11), status d0 error d0 (mask 0x40 bits 0x40)
    [repeated 10 times]

Brian.

-- 
  Brian de Alwis | Software Practices Lab | UBC | http://www.cs.ubc.ca/~bsd/
      "Amusement to an observing mind is study." - Benjamin Disraeli