From owner-freebsd-scsi@FreeBSD.ORG Fri Jan 21 13:58:19 2005 Return-Path: Delivered-To: freebsd-scsi@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 6C59516A4CE for ; Fri, 21 Jan 2005 13:58:19 +0000 (GMT) Received: from heechee.tobez.org (heechee.tobez.org [217.157.39.226]) by mx1.FreeBSD.org (Postfix) with ESMTP id 16C2F43D31 for ; Fri, 21 Jan 2005 13:58:18 +0000 (GMT) (envelope-from tobez@tobez.org) Received: by heechee.tobez.org (Postfix, from userid 1001) id B4FCC125425; Fri, 21 Jan 2005 14:58:14 +0100 (CET) Date: Fri, 21 Jan 2005 14:58:14 +0100 From: Anton Berezin To: freebsd-scsi@freebsd.org Message-ID: <20050121135814.GA35988@heechee.tobez.org> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline User-Agent: Mutt/1.4.2.1i Subject: 29320A: tons of "unexpected busfree while idle" X-BeenThere: freebsd-scsi@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: SCSI subsystem List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 21 Jan 2005 13:58:19 -0000 Hi, I am having a lot of "unexpected busfree while idle" events with Adaptec 29320A Ultra320 SCSI adapter. While trying to eliminate various possibilities, it turned out that the problem disappears if I downgrade sys/dev/aic7xxx directory to -D '01 Sep 2004' -rRELENG_5 So it looks like the problem was introduced sometime after that. Other things we've tried, which did not help, with a single exception: - using fresh RELENG_5 driver; - using fresh HEAD driver; - sticking this PCIX card into a normal PCI slot; - sticking the card into a 5.3 Athlon64 box (also normal PCI); - using different cables; - using FreeBSD 4.8 (the problem disappeared here, too). More details: Jan 18 10:15:56 seifert kernel: ahd0: port 0xb400-0xb4ff,0xb800-0xb8ff mem 0xfc5fe000-0xfc5fffff irq 26 at device 4.0 on pci2 Jan 18 10:15:56 seifert kernel: ahd0: [GIANT-LOCKED] Jan 18 10:15:56 seifert kernel: aic7901: Ultra320 Wide Channel A, SCSI Id=7, PCI-X 50-66Mhz, 512 SCBs Jan 18 10:15:56 seifert kernel: ahd0: Unexpected busfree while idle, 0 SCBs aborted, PRGMCNT == 0xb9 Jan 18 10:15:56 seifert kernel: >>>>>>>>>>>>>>>>>> Dump Card State Begins <<<<<<<<<<<<<<<<< Jan 18 10:15:56 seifert kernel: ahd0: Dumping Card State at program address 0xb7 Mode 0x33 Jan 18 10:15:56 seifert kernel: Card was paused Jan 18 10:15:56 seifert kernel: INTSTAT[0x8] SELOID[0x4] SELID[0x0] HS_MAILBOX[0x0] Jan 18 10:15:56 seifert kernel: INTCTL[0x80] SEQINTSTAT[0x0] SAVED_MODE[0x11] DFFSTAT[0x33] Jan 18 10:15:56 seifert kernel: SCSISIGI[0xe6] SCSIPHASE[0x8] SCSIBUS[0x80] LASTPHASE[0x1] Jan 18 10:15:56 seifert kernel: SCSISEQ0[0x0] SCSISEQ1[0x12] SEQCTL0[0x0] SEQINTCTL[0x0] Jan 18 10:15:56 seifert kernel: SEQ_FLAGS[0xc0] SEQ_FLAGS2[0x0] QFREEZE_COUNT[0x2] Jan 18 10:15:56 seifert kernel: KERNEL_QFREEZE_COUNT[0x2] MK_MESSAGE_SCB[0xff00] MK_MESSAGE_SCSIID[0xff] Jan 18 10:15:56 seifert kernel: SSTAT0[0x22] SSTAT1[0x19] SSTAT2[0x10] SSTAT3[0x0] Jan 18 10:15:56 seifert kernel: PERRDIAG[0x0] SIMODE1[0xac] LQISTAT0[0x0] LQISTAT1[0x0] Jan 18 10:15:56 seifert kernel: LQISTAT2[0x0] LQOSTAT0[0x0] LQOSTAT1[0x0] LQOSTAT2[0x0] Jan 18 10:15:56 seifert kernel: Jan 18 10:15:56 seifert kernel: SCB Count = 16 CMDS_PENDING = 2 LASTSCB 0xffff CURRSCB 0xb NEXTSCB 0x0 Jan 18 10:15:56 seifert kernel: qinstart = 23 qinfifonext = 23 Jan 18 10:15:56 seifert kernel: QINFIFO: Jan 18 10:15:56 seifert kernel: WAITING_TID_QUEUES: Jan 18 10:15:56 seifert kernel: Pending list: Jan 18 10:15:56 seifert kernel: 11 FIFO_USE[0x0] SCB_CONTROL[0x44] SCB_SCSIID[0x47] Jan 18 10:15:56 seifert kernel: 15 FIFO_USE[0x0] SCB_CONTROL[0x44] SCB_SCSIID[0x7] Jan 18 10:15:56 seifert kernel: Total 2 Jan 18 10:15:56 seifert kernel: Kernel Free SCB list: 1 2 3 4 5 6 7 8 9 10 12 13 14 0 Jan 18 10:15:56 seifert kernel: Sequencer Complete DMA-inprog list: Jan 18 10:15:56 seifert kernel: Sequencer Complete list: Jan 18 10:15:56 seifert kernel: Sequencer DMA-Up and Complete list: Jan 18 10:15:56 seifert kernel: Sequencer On QFreeze and Complete list: Jan 18 10:15:56 seifert kernel: Jan 18 10:15:56 seifert kernel: Jan 18 10:15:56 seifert kernel: ahd0: FIFO0 Free, LONGJMP == 0x80ff, SCB 0x0 Jan 18 10:15:56 seifert kernel: SEQIMODE[0x3f] SEQINTSRC[0x0] DFCNTRL[0x0] DFSTATUS[0x89] Jan 18 10:15:56 seifert kernel: SG_CACHE_SHADOW[0x2] SG_STATE[0x0] DFFSXFRCTL[0x0] Jan 18 10:15:56 seifert kernel: SOFFCNT[0x0] MDFFSTAT[0x5] SHADDR = 0x00, SHCNT = 0x0 Jan 18 10:15:56 seifert kernel: HADDR = 0x00, HCNT = 0x0 CCSGCTL[0x10] Jan 18 10:15:56 seifert kernel: Jan 18 10:15:56 seifert kernel: ahd0: FIFO1 Free, LONGJMP == 0x8063, SCB 0xb Jan 18 10:15:56 seifert kernel: SEQIMODE[0x3f] SEQINTSRC[0x0] DFCNTRL[0x4] DFSTATUS[0x89] Jan 18 10:15:56 seifert kernel: SG_CACHE_SHADOW[0x2] SG_STATE[0x0] DFFSXFRCTL[0x0] Jan 18 10:15:56 seifert kernel: SOFFCNT[0x0] MDFFSTAT[0x5] SHADDR = 0x00, SHCNT = 0x0 Jan 18 10:15:56 seifert kernel: HADDR = 0x00, HCNT = 0x0 CCSGCTL[0x10] Jan 18 10:15:56 seifert kernel: LQIN: 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 Jan 18 10:15:56 seifert kernel: ahd0: LQISTATE = 0x0, LQOSTATE = 0x0, OPTIONMODE = 0x42 Jan 18 10:15:56 seifert kernel: ahd0: OS_SPACE_CNT = 0x20 MAXCMDCNT = 0x0 Jan 18 10:15:56 seifert kernel: ahd0: SAVED_SCSIID = 0x0 SAVED_LUN = 0x0 Jan 18 10:15:56 seifert kernel: SIMODE0[0xc] Jan 18 10:15:56 seifert kernel: CCSCBCTL[0x4] Jan 18 10:15:56 seifert kernel: ahd0: REG0 == 0xb, SINDEX = 0x1b8, DINDEX = 0x1ba Jan 18 10:15:56 seifert kernel: ahd0: SCBPTR == 0xb, SCB_NEXT == 0xff00, SCB_NEXT2 == 0xff72 Jan 18 10:15:56 seifert kernel: CDB 1a 0 a 0 14 0 Jan 18 10:15:56 seifert kernel: STACK: 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 Jan 18 10:15:56 seifert kernel: <<<<<<<<<<<<<<<<< Dump Card State Ends >>>>>>>>>>>>>>>>>> This kind of dump happens sometime during disk probe, almost never during newfs, and always, massively, during moderately intensive disk operations (cp -pr ncvs, rm -rf ncvs etc). Another strangety is how the thing recognizes the disks (any version of the driver): Jan 18 10:15:56 seifert kernel: da0 at ahd0 bus 0 target 0 lun 0 Jan 18 10:15:56 seifert kernel: da0: Fixed Direct Access SCSI-3 device Jan 18 10:15:56 seifert kernel: da0: 40.000MB/s transfers (20.000MHz, offset 81, 16bit), Tagged Queueing Enabled Jan 18 10:15:56 seifert kernel: da0: 70513MB (144410880 512 byte sectors: 255H 63S/T 8989C) Jan 18 10:15:56 seifert kernel: da1 at ahd0 bus 0 target 4 lun 0 Jan 18 10:15:56 seifert kernel: da1: Fixed Direct Access SCSI-3 device Jan 18 10:15:56 seifert kernel: da1: 40.000MB/s transfers (20.000MHz, offset 81, 16bit), Tagged Queueing Enabled Jan 18 10:15:56 seifert kernel: da1: 70513MB (144410880 512 byte sectors: 255H 63S/T 8989C) According to Hitachi specs, those 15k RPM disks can sustain 79MB/s, so why are they reported as 40MB/s disks? In reality, I was able to get about 36MB/s out of them with the before-september driver. Any thoughts? Thanks, \Anton. -- The moronity of the universe is a monotonically increasing function. -- Jarkko Hietaniemi