Linux-2.1.54 + 2940AU: Unexpected bus free report.
Simon Park
si at nemesis.demon.co.uk
Tue Sep 9 15:14:59 PDT 1997
Hi,
I have a problem playing audio CDs that seems to tickle a bug in the
aic7xxx reset/abort code that occurs when skipping to the next track.
This is using linux 2.1.54 with Doug's Sept-5 abort patch.
My hardware is a Supermicro P6DNE with a single 200Mhz PPro, AHA-2940AU,
Seagate ST3500N (id:0) and a Pioneer DR-124X CDROM (id:6).
The ST3500N has small partition with linux on for testing new SCSI
software before subjecting my 'real' filesystems. Swap is also to the
ST3500N.
The 2940 has BIOS v1.21 and has the default settings apart from having
SCAM enabled.
aic7xxx_verbose is set to 5.
Scenario:
Boot linux, start workbone, use skip-to-next-track or skip-to-previous-track
keys.
Symptoms:
I always get TARGET_BUSY warnings each time I skip a track. After several
skips I start getting the reset messages.
Logs follow:
-------- cat /proc/scsi/aic7xxx/0 --------------
Adaptec AIC7xxx driver version: 4.1.1/3.2.1
Compile Options:
AIC7XXX_RESET_DELAY : 15
AIC7XXX_TAGGED_QUEUEING: Enabled
AIC7XXX_PAGE_ENABLE : Enabled
AIC7XXX_PROC_STATS : Disabled
Adapter Configuration:
SCSI Adapter: Adaptec AHA-2940A Ultra SCSI host adapter
(AIC-786x chipset)
Host Bus: Single
Base IO: 0xec00
Base IO Memory: 0xfebef000
IRQ: 11
SCBs: Used 4, HW 3, Page 8
Interrupts: 579
Serial EEPROM: True
Extended Translation: Enabled
SCSI Bus Reset: Enabled
Ultra SCSI: Disabled
Target Disconnect: Enabled
----------- cat /tmp/klog.out ------------------
Kernel logging (proc) started.
<4>Memory: sized by int13 088h
<4>Intel MultiProcessor Specification v1.1
<4> Virtual Wire compatibility mode.
<4>OEM ID: INTEL Product ID: 440FX APIC at: 0xFEE00000
<4>Processor #0 Pentium(tm) Pro APIC version 17
<4>I/O APIC #2 Version 17 at 0xFEC00000.
<4>Processors: 1
<4>Console: 16 point font, 400 scans
<4>Console: colour VGA+ 80x25, 1 virtual console (max 63)
<4>PCI: BIOS32 Service Directory structure at 0xc00fdb70
<4>PCI: BIOS32 Service Directory entry at 0xfdb80
<4>PCI: PCI BIOS revision 2.10 entry at 0xfdba1
<4>Probing PCI hardware.
<4>Calibrating delay loop.. ok - 199.07 BogoMIPS
<4>Memory: 22964k/24576k available (704k kernel code, 400k reserved, 488k data, 20k init)
<6>Swansea University Computer Society NET3.039 for Linux 2.1
<6>NET3: Unix domain sockets 0.16 for Linux NET3.038.
<6>Swansea University Computer Society TCP/IP for NET3.037
<6>IP Protocols: IGMP, ICMP, UDP, TCP
<6>Checking 386/387 coupling... Ok, fpu using exception 16 error reporting.
<6>Checking 'hlt' instruction... Ok.
<4>Linux version 2.1.54 (root at nemesis) (gcc version 2.7.2.1) #4 Mon Sep 8 21:54:50 BST 1997
<4>POSIX conformance testing by UNIFIX
<4>calibrating APIC timer ...
<4>..... CPU clock speed is 199.4440 MHz.
<4>..... APIC bus clock speed is 66.4811 MHz.
<4>Error: only one processor found.
<4>Starting kswapd v 1.23
<4>PIIX3: bus-master IDE device on PCI bus 0 function 57
<4> ide0: BM-DMA at 0xffa0-0xffa7
<4> ide0 master/slave: sample_CLKs=3, recovery_CLKs=1
<4> master: fastDMA=yes PreFetch=on IORDY=on fastPIO=on
<4> slave : fastDMA=no PreFetch=off IORDY=off fastPIO=off
<4> ide1: BM-DMA at 0xffa8-0xffaf
<4> ide1 master/slave: sample_CLKs=5, recovery_CLKs=4
<4> master: fastDMA=no PreFetch=off IORDY=off fastPIO=off
<4> slave : fastDMA=no PreFetch=off IORDY=off fastPIO=off
<4>hda: QUANTUM FIREBALL_TM3200A, ATA DISK drive
<4>ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
<4>hda: DMA disabled
<6>hda: QUANTUM FIREBALL_TM3200A, 3067MB w/76kB Cache, LBA, CHS=779/128/63
<6>aic7xxx: Driver modifications performed by Doug Ledford, Aug-Sep, 1997
<4>aic7xxx: This version is not supported by the official aic7xxx maintainer
<4>aic7xxx: Please email problems/questions directly to dledford at dialnet.net
<4>aic7xxx: <Adaptec AHA-2940A Ultra SCSI host adapter> at PCI 18
<6>aic7xxx: Loading serial EEPROM...done
<6>aic7xxx: Warning - detected auto-termination. Please verify driver
<6> detected settings and use manual termination if necessary.
<6>aic7xxx: Cables present (Int-50 YES, Ext-50 NO)
<6>aic7xxx: eprom not present, brdctl_int=0xc, brdctl_ext=0x4c
<6>aic7xxx: Termination ON
<6>aic7xxx: BIOS enabled, IO Port 0xec00, IO Mem 0xfebef000, IRQ 11, Revision C
<6>aic7xxx: Extended translation enabled.
<6>aic7xxx: Single Channel, SCSI ID 7, 3/8 SCBs, QFull 8, QMask 0xf
<6>aic7xxx: Resetting channel A
<6>aic7xxx: Downloading sequencer code... 414 instructions downloaded
<4>scsi0 : Adaptec AHA274x/284x/294x (EISA/VLB/PCI-Fast SCSI) 4.1.1/3.2.1
<4>scsi : 1 host.
<6>scsi0: Scanning channel A for devices.
<4>scsi0: Target 0, channel A, now synchronous at 10.0MHz, offset 15.
<4> Vendor: SEAGATE Model: ST3500N Rev: 7824
<4> Type: Direct-Access ANSI SCSI revision: 02
<4>Detected scsi disk sda at scsi0, channel 0, id 0, lun 0
<4>scsi0: Target 6, channel A, now synchronous at 4.4MHz, offset 8.
<4> Vendor: PIONEER Model: CD-ROM DR-124X Rev: 1.01
<4> Type: CD-ROM ANSI SCSI revision: 02
<6>(scsi0:0:0) Enabled tagged queuing, queue depth 4.
<4>scsi : detected 1 SCSI disk total.
<4>SCSI device sda: hdwr sector= 512 bytes. Sectors= 833245 [406 MB] [0.4 GB]
<4>Partition check:
<4> sda: sda1 sda2 sda3
<4> hda: hda1 hda2 < hda5 hda6 hda7 >
<4>VFS: Mounted root (ext2 filesystem) readonly.
<4>Freeing unused kernel memory: 20k freed
<4>Adding Swap: 66556k swap-space (priority -1)
// Started workbone
<6>Module cdrom: Generic CDROM driver $Revision: 1.7 $
<4>Detected scsi CD-ROM sr0 at scsi0, channel 0, id 6, lun 0
<6>Disc change detected.
<7>VFS: Disk change detected on device 0b:00
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track starts playing
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
// Press next track (Numpad 6), track does not play
<4>(scsi0:6:0) Target busy
<4>(scsi0:0:6): Missed busfree.
<4>(scsi0:-1:-1) Timer running.
<4>(scsi0:6:0) Reset called, scb 2, flags 0x1
<4>(scsi0:6:0) Bus Device reset, scb flags 0x1, while idle, LASTPHASE = 0x1, SCSISIGI 0x86, SEQADDR 0x6, SSTAT0 0x7, SSTAT1 0x13
<4>(scsi0:6:0) Queueing device reset command.
<4>(scsi0:6:0) Bus device reset mailed.
<4>(scsi0:6:0) Reset device, active_scb 2
<4>(scsi0:8:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:6:0) Cleaning QINFIFO.
<4>scsi0: (targ 6/chan A) matching scb to (targ 0/chan A)
<4>(scsi0:6:0) Cleaning waiting_scbs.
<4>(scsi0:6:0) Cleaning waiting for selection list.
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>scsi0: (targ 6/chan A) matching scb to (targ 0/chan A)
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>(scsi0:6:0) Bus Device Reset delivered.
<4>(scsi0:6:0) Aborting scb 2
<4>(scsi0:-1:-1) 1 commands found and queued for completion.
<4>(scsi0:6:0) Reset device, active_scb 0
<4>(scsi0:8:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:6:0) Cleaning QINFIFO.
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>(scsi0:6:0) Cleaning waiting_scbs.
<4>(scsi0:6:0) Cleaning waiting for selection list.
<4>scsi0: (targ 6/chan A) matching scb to (targ 0/chan A)
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>scsi0: (targ 6/chan A) matching scb to (targ 0/chan A)
<4>scsi0: (targ 6/chan A) matching scb to (targ 0/chan A)
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>(scsi0:6:0) Aborting scb 2
<4>(scsi0:6:0) Aborting scb 3
<4>(scsi0:-1:-1) 2 commands found and queued for completion.
<4>scsi0: Unexpected busfree, LASTPHASE = 0x1, SEQADDR = 0x48
<4>scsi : aborting command due to timeout : pid 775, scsi0, channel 0, id 6, lun 0 UNKNOWN(0x47) 00 00 1e 37 23 4d 08 4a 00
<4>(scsi0:6:0) Reset/Abort pending for this device, not wasting our time.
<4>SCSI host 0 abort (pid 775) timed out - resetting
<4>SCSI bus is being reset for host 0 channel 0.
<4>(scsi0:6:0) Reset called, scb 3, flags 0x1
<4>(scsi0:6:0) Bus device reset already sent to device, escalating.
<4>(scsi0:-1:0) Reset channel called, will initiate reset.
<4>(scsi0:-1:0) Resetting currently active channel.
<4>(scsi0:-1:0) Channel reset
<4>(scsi0:-1:0) Reset device, active_scb 1
<4>(scsi0:0:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:1:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:2:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:3:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:4:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:5:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:6:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:7:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:-1:0) Cleaning QINFIFO.
<4>(scsi0:-1:0) Cleaning waiting_scbs.
<4>(scsi0:-1:0) Cleaning waiting for selection list.
<4>scsi0: (targ -1/chan A) matching scb to (targ 6/chan A)
<4>scsi0: (targ -1/chan A) matching scb to (targ 6/chan A)
<4>scsi0: (targ -1/chan A) matching scb to (targ 6/chan A)
<4>(scsi0:6:0) Aborting scb 2
<4>(scsi0:6:0) Aborting scb 3
<4>(scsi0:-1:-1) 2 commands found and queued for completion.
<4>scsi0: Target 6, channel A, now synchronous at 3.6MHz, offset 8.
<4>scsi0: Target 0, channel A, now synchronous at 10.0MHz, offset 15.
<4>(scsi0:6:0) Target busy
<4>(scsi0:-1:-1) Timer running.
<4>(scsi0:6:0) Reset called, scb 3, flags 0x1
<4>(scsi0:6:0) Reset called too soon after last bus reset, delaying.
<4>scsi : aborting command due to timeout : pid 787, scsi0, channel 0, id 6, lun 0 UNKNOWN(0x47) 00 00 22 29 0a 4d 08 4a 00
<4>(scsi0:6:0) Aborting scb 3, flags 0x1
<4>(scsi0:6:0) SCB disconnected. Queueing Abort SCB.
<4>(scsi0:6:0) Abort message mailed.
<4>(scsi0:6:0) SCB 3 abort delivered.
<4>(scsi0:6:0) Reset device, active_scb 0
<4>(scsi0:8:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:6:0) Cleaning QINFIFO.
<4>(scsi0:6:0) Cleaning waiting_scbs.
<4>(scsi0:6:0) Cleaning waiting for selection list.
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>(scsi0:6:0) Aborting scb 3
<4>(scsi0:-1:-1) 1 commands found and queued for completion.
<4>(scsi0:6:0) Reset device, active_scb 3
<4>(scsi0:8:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:6:0) Cleaning QINFIFO.
<4>(scsi0:6:0) Cleaning waiting_scbs.
<4>(scsi0:6:0) Cleaning waiting for selection list.
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>scsi0: (targ 6/chan A) matching scb to (targ 6/chan A)
<4>(scsi0:6:0) Aborting scb 3
<4>(scsi0:-1:-1) 1 commands found and queued for completion.
<4>scsi0: Unexpected busfree, LASTPHASE = 0xe0, SEQADDR = 0x48
<4>SCSI host 0 abort (pid 787) timed out - resetting
<4>SCSI bus is being reset for host 0 channel 0.
<4>(scsi0:6:0) Reset called, scb 3, flags 0x1
<4>(scsi0:6:0) Bus Device reset, scb flags 0x1, while idle, LASTPHASE = 0x1, SCSISIGI 0x0, SEQADDR 0x5, SSTAT0 0x5, SSTAT1 0xa
<4>SCSI host 0 channel 0 reset (pid 787) timed out - trying harder
<4>SCSI bus is being reset for host 0 channel 0.
<4>(scsi0:6:0) Reset called, scb 3, flags 0x1
<4>(scsi0:-1:0) Reset channel called, will initiate reset.
<4>(scsi0:-1:0) Resetting currently active channel.
<4>(scsi0:-1:0) Channel reset
<4>(scsi0:-1:0) Reset device, active_scb 2
<4>(scsi0:0:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:1:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:2:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:3:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:4:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:5:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:6:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:7:0) Cleaning up status information and delayed_scbs.
<4>(scsi0:-1:0) Cleaning QINFIFO.
<4>(scsi0:-1:0) Cleaning waiting_scbs.
<4>(scsi0:-1:0) Cleaning waiting for selection list.
<4>scsi0: (targ -1/chan A) matching scb to (targ 6/chan A)
<4>(scsi0:6:0) Aborting scb 3
<4>(scsi0:-1:-1) 1 commands found and queued for completion.
<4>scsi0: Target 6, channel A, now synchronous at 3.6MHz, offset 8.
<4>scsi0: Target 0, channel A, now synchronous at 10.0MHz, offset 15.
// Cdrom recovers and plays track
// Quit workbone
// Reboot
Kernel logging (proc) stopped.
Kernel log daemon terminating.
-----------------------------------------------
BTW Doug, The abort patch is a great step in the right direction, thanks.
The behaviour of stock 2.1.54 with the above tests results in tens of
target busy messages followed by a bus reset and then a kernel panic
(NULL pointer defererence) !
Also in 2.1.54 + patch there is one remaining use of the NUMBER() macro
that still has <= in a for() loop, search for NUMBER(aic7xxx_boards). This
doesn't look right to me. Should it be < rather than <= ?
Cheers
Si
More information about the aic7xxx
mailing list